lightning
lightning copied to clipboard
ElementsProject
Thousands of "Transaction already in block chain" sendrawtx errors every time lightningd is restarted
Issue and Steps to Reproduce
For quite a while after starting lightningd, the debug log shows that thousands of sendrawtx commands are being issued for the same few transactions over and over.
It's not clear to me where the cycle begins and ends since it repeats, but here's a sample of it:
2022-05-30T07:40:40.895Z DEBUG 03…83-onchaind-chan#153256: FUNDING_TRANSACTION/FUNDING_OUTPUT->OUR_UNILATERAL depth 23651
2022-05-30T07:40:40.896Z DEBUG 03…83-onchaind-chan#153256: Broadcasting OUR_HTLC_TIMEOUT_TX (02…00) to resolve OUR_UNILATERAL/OUR_HTLC
2022-05-30T07:40:40.899Z DEBUG lightningd: Broadcasting txid f6…d6
2022-05-30T07:40:40.899Z DEBUG lightningd: sendrawtransaction: 02…00
2022-05-30T07:40:40.904Z DEBUG plugin-bcli: sendrawtx exit 27 (bitcoin-cli -datadir=/var/lib/bitcoind sendrawtransaction 02…00) error code: -27\nerror message:\nTransaction already in block chain
2022-05-30T07:40:40.911Z DEBUG 03…83-onchaind-chan#153256: OUR_UNILATERAL/OUTPUT_TO_THEM->SELF depth 23651
2022-05-30T07:40:40.913Z DEBUG 03…83-onchaind-chan#153256: billboard: 1 outputs unresolved: waiting confirmation that we spent OUR_HTLC (c7…72:0) using OUR_HTLC_TIMEOUT_TX
2022-05-30T07:40:40.914Z DEBUG 03…83-onchaind-chan#153256: Got new message WIRE_ONCHAIND_DEPTH
2022-05-30T07:40:40.914Z DEBUG 03…83-onchaind-chan#153256: OUR_UNILATERAL/DELAYED_OUTPUT_TO_US->OUR_DELAYED_RETURN_TO_WALLET depth 21838
2022-05-30T07:40:40.915Z DEBUG 03…83-onchaind-chan#153256: billboard: 1 outputs unresolved: waiting confirmation that we spent OUR_HTLC (c7…72:0) using OUR_HTLC_TIMEOUT_TX
2022-05-30T07:40:40.916Z DEBUG 03…83-onchaind-chan#153256: Got new message WIRE_ONCHAIND_DEPTH
2022-05-30T07:40:40.918Z DEBUG 03…83-onchaind-chan#153256: FUNDING_TRANSACTION/FUNDING_OUTPUT->OUR_UNILATERAL depth 23652
2022-05-30T07:40:40.919Z DEBUG 03…83-onchaind-chan#153256: Broadcasting OUR_HTLC_TIMEOUT_TX (02…00) to resolve OUR_UNILATERAL/OUR_HTLC
2022-05-30T07:40:40.920Z DEBUG lightningd: Broadcasting txid f6…d6
2022-05-30T07:40:40.921Z DEBUG lightningd: sendrawtransaction: 02…00
2022-05-30T07:40:40.926Z DEBUG plugin-bcli: sendrawtx exit 27 (bitcoin-cli -datadir=/var/lib/bitcoind sendrawtransaction 02…00) error code: -27\nerror message:\nTransaction already in block chain
2022-05-30T07:40:40.936Z DEBUG 03…83-onchaind-chan#153256: OUR_UNILATERAL/OUTPUT_TO_THEM->SELF depth 23652
2022-05-30T07:40:40.937Z DEBUG 03…83-onchaind-chan#153256: billboard: 1 outputs unresolved: waiting confirmation that we spent OUR_HTLC (c7…72:0) using OUR_HTLC_TIMEOUT_TX
2022-05-30T07:40:40.938Z DEBUG 03…83-onchaind-chan#153256: Got new message WIRE_ONCHAIND_DEPTH
2022-05-30T07:40:40.939Z DEBUG 03…83-onchaind-chan#153256: OUR_UNILATERAL/DELAYED_OUTPUT_TO_US->OUR_DELAYED_RETURN_TO_WALLET depth 21839
2022-05-30T07:40:40.940Z DEBUG 03…83-onchaind-chan#153256: billboard: 1 outputs unresolved: waiting confirmation that we spent OUR_HTLC (c7…72:0) using OUR_HTLC_TIMEOUT_TX
2022-05-30T07:40:40.943Z DEBUG 03…83-onchaind-chan#153256: Got new message WIRE_ONCHAIND_DEPTH
2022-05-30T07:40:40.944Z DEBUG 03…83-onchaind-chan#153256: FUNDING_TRANSACTION/FUNDING_OUTPUT->OUR_UNILATERAL depth 23653
(And so on.)
Notice the incrementing depth counter. Eventually lightningd does calm down and stop issuing all those sendrawtx calls once the depth "catches up" to the present, but then if I restart lightningd, it starts all over again.
getinfo output
This is version 0.11.1.
This problem is getting worse. As these defunct channels continue to age, the number of blocks that they must "catch up" at lightningd startup is forever increasing. Here is the (redacted) listpeers output for the peer that I reported about when I opened this issue back in May:
{
"peers": [
{
"id": "03…83",
"connected": false,
"channels": [
{
"state": "ONCHAIN",
"scratch_txid": "c7…72",
"last_tx_fee": "2757000msat",
"last_tx_fee_msat": "2757000msat",
"feerate": {
"perkw": 3076,
"perkb": 12304
},
"owner": "onchaind",
"short_channel_id": "…06x…71x0",
"direction": 0,
"channel_id": "82…3a",
"funding_txid": "3a…82",
"funding_outnum": 0,
"close_to_addr": "bc1qzr07tfh8x9m9dcwg7rj9hv2g037vnfh2kqdt3c",
"close_to": "00…ea",
"private": false,
"opener": "remote",
"closer": "remote",
"features": [
"option_static_remotekey"
],
"funding_allocation_msat": {
"03…83": 15000000000,
"02…2f": 0
},
"funding_msat": {
"03…83": "15000000000msat",
"02…2f": "0msat"
},
"funding": {
"local_msat": "0msat",
"remote_msat": "15000000000msat",
"pushed_msat": "0msat"
},
"msatoshi_to_us": 8203646918,
"to_us_msat": "8203646918msat",
"msatoshi_to_us_min": 0,
"min_to_us_msat": "0msat",
"msatoshi_to_us_max": 14848851901,
"max_to_us_msat": "14848851901msat",
"msatoshi_total": 15000000000,
"total_msat": "15000000000msat",
"fee_base_msat": "0msat",
"fee_proportional_millionths": 11,
"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": 150000,
"their_reserve_msat": "150000000msat",
"our_channel_reserve_satoshis": 150000,
"our_reserve_msat": "150000000msat",
"spendable_msatoshi": 4294967295,
"spendable_msat": "4294967295msat",
"receivable_msatoshi": 4294967295,
"receivable_msat": "4294967295msat",
"htlc_minimum_msat": 0,
"minimum_htlc_in_msat": "0msat",
"minimum_htlc_out_msat": "1msat",
"maximum_htlc_out_msat": "14850000000msat",
"their_to_self_delay": 432,
"our_to_self_delay": 1802,
"max_accepted_htlcs": 5,
"state_changes": [
{
"timestamp": "2021-07-16T01:30:07.038Z",
"old_state": "CHANNELD_AWAITING_LOCKIN",
"new_state": "CHANNELD_NORMAL",
"cause": "remote",
"message": "Lockin complete"
},
{
"timestamp": "2021-12-04T12:19:07.794Z",
"old_state": "CHANNELD_NORMAL",
"new_state": "AWAITING_UNILATERAL",
"cause": "protocol",
"message": "Offered HTLC 7596 SENT_ADD_COMMIT cltv 712557 hit deadline"
},
{
"timestamp": "2021-12-04T12:32:38.967Z",
"old_state": "AWAITING_UNILATERAL",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2021-12-04T12:32:39.291Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2021-12-16T08:12:21.106Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2021-12-16T08:12:29.061Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2021-12-25T09:48:58.119Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2021-12-25T09:49:04.388Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-01-04T08:56:14.362Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-01-04T08:56:20.257Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-01-04T08:57:35.833Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-01-04T08:57:42.762Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-01-04T09:07:16.126Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-01-04T09:07:22.029Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-01-04T09:26:49.921Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-01-04T09:26:55.547Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-01-07T10:26:35.655Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-01-07T10:26:37.793Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-01-16T07:51:29.588Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-01-16T07:51:40.737Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-02-09T03:34:47.153Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-02-09T03:35:14.131Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-02-09T12:06:23.334Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-02-09T12:06:39.993Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-02-09T12:10:59.683Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-02-09T12:11:24.445Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-02-10T11:16:18.985Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-02-10T11:16:43.009Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-02-11T07:14:22.271Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-02-11T07:14:28.545Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-02-12T07:44:27.069Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-02-12T07:44:30.809Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-02-12T10:03:24.024Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-02-12T10:03:29.037Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-02-12T12:23:06.207Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-02-12T12:23:08.992Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-02-22T03:47:36.780Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-02-22T04:25:45.285Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-03-14T07:12:46.057Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-03-14T07:13:00.980Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-04-21T00:01:09.377Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-04-21T00:01:25.145Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-04-22T19:58:53.305Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-04-22T19:59:08.335Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-04-22T20:06:33.444Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-04-22T20:06:48.130Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-05-28T20:56:15.235Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-05-28T20:56:50.654Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-05-30T05:23:31.755Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-05-30T05:23:50.581Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-05-30T05:27:15.451Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-05-30T05:27:30.588Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-05-30T05:43:27.931Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-05-30T05:43:40.053Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-05-30T06:16:21.717Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-05-30T06:16:34.511Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-05-30T07:18:29.827Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-05-30T07:18:41.746Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-06-01T06:41:24.119Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-06-01T06:41:50.032Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-06-01T07:07:20.586Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-06-01T07:07:41.448Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-06-01T07:20:36.428Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-06-01T07:20:57.748Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-06-07T14:45:14.943Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-06-07T14:45:44.598Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-06-08T05:55:47.076Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-06-08T05:56:27.552Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-06-08T06:31:19.784Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-06-08T06:31:55.298Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-06-08T06:34:20.739Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-06-08T06:34:57.423Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-06-08T06:40:43.441Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-06-08T06:41:19.357Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-06-12T23:55:33.961Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-06-12T23:56:56.536Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-06-26T20:15:15.811Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-06-26T20:15:44.566Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-06-27T05:41:18.615Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-06-27T05:41:44.636Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-06-28T09:04:15.500Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-06-28T09:05:16.656Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-06-28T09:29:55.011Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-06-28T09:30:36.921Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-07-22T09:31:23.854Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-07-22T09:31:41.338Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-08-28T05:53:53.861Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-08-28T06:32:23.489Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-08-28T06:58:10.985Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-08-28T06:58:44.700Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-08-28T07:04:21.223Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-08-28T07:04:53.501Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-08-29T09:15:27.388Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-08-29T09:16:11.661Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-08-29T09:44:31.050Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-08-29T09:45:10.526Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-08-29T10:14:07.789Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-08-29T10:14:47.778Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-09-22T23:44:00.070Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-09-22T23:44:47.299Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
},
{
"timestamp": "2022-09-26T08:05:27.614Z",
"old_state": "ONCHAIN",
"new_state": "FUNDING_SPEND_SEEN",
"cause": "onchain",
"message": "Onchain funding spend"
},
{
"timestamp": "2022-09-26T08:06:16.786Z",
"old_state": "FUNDING_SPEND_SEEN",
"new_state": "ONCHAIN",
"cause": "onchain",
"message": "Onchain init reply"
}
],
"status": [
"ONCHAIN:Tracking our own unilateral close",
"ONCHAIN:1 outputs unresolved: waiting confirmation that we spent OUR_HTLC (c7…72:0) using OUR_HTLC_TIMEOUT_TX"
],
"in_payments_offered": 7540,
"in_msatoshi_offered": 2066248626504,
"in_offered_msat": "2066248626504msat",
"in_payments_fulfilled": 1707,
"in_msatoshi_fulfilled": 80211486967,
"in_fulfilled_msat": "80211486967msat",
"out_payments_offered": 7597,
"out_msatoshi_offered": 1101358314073,
"out_offered_msat": "1101358314073msat",
"out_payments_fulfilled": 2621,
"out_msatoshi_fulfilled": 72007840049,
"out_fulfilled_msat": "72007840049msat",
"htlcs": [
{
"direction": "out",
"id": 7595,
"msatoshi": 287901823,
"amount_msat": "287901823msat",
"expiry": 712628,
"payment_hash": "48…ce",
"state": "SENT_ADD_ACK_REVOCATION"
},
{
"direction": "out",
"id": 7596,
"msatoshi": 50002200,
"amount_msat": "50002200msat",
"expiry": 712557,
"payment_hash": "de…e7",
"state": "RCVD_REMOVE_HTLC"
}
]
}
]
}
]
}
Notice the long sequence of state_changes toggling back and forth between FUNDING_SPEND_SEEN and ONCHAIN. The dates correspond to every time I restarted my node.
I'd really like to purge these troublesome channels so my node can be restarted without becoming inoperative for hours while it spams bitcoind with pointless sendrawtransaction commands. How can I tell whether it is safe to dev-forget-channel a channel? Am I correct in thinking that it is safe to forget a channel if all outputs of its commitment transaction have been spent and all outputs of those spending transactions have also been spent?
Do you still have this problem in 0.12.1 ? I'm thinking about upgrading because of this problem... Any idea what to do @rustyrussell ?
@manreo: I haven't taken the plunge into 0.12.x yet. I can confirm that this problem does still occur on my 0.11.2/backports branch, which contains most of the fixes and minor enhancements from 0.12.x. In my very thorough perusal of the commits in between v0.11.2 and master, I did not see any that appeared as though they might attempt to address this problem.
I have multiple channels that are all stuck in this state, so I believe we have an edge case here that needs closing up. The channels were all force-closed by my node due to HTLCs having reached their deadlines. The closures occurred over a period of time spanning from 2021-12-04 to 2022-05-21.
In all cases:
- My node is stuck on "
waiting confirmation that we spent OUR_HTLCusing OUR_HTLC_TIMEOUT_TX." - Each such
OUR_HTLC_TIMEOUT_TXhas in fact been confirmed on the block chain for many months. - The single P2WSH output of each
OUR_HTLC_TIMEOUT_TXremains unspent to this day.
Here are some listpeers excerpts showing the statuses of my channels that are stuck in this limbo state:
$ for peer in 02…71 03…83 03…81 03…95 03…8a 02…0c 03…b4 02…df ; do lightning-cli listpeers "${peer}" ; done | jq '.peers[].channels[] | select(.state == "ONCHAIN") | { state_changes: [.state_changes[] | select(.new_state == "AWAITING_UNILATERAL")], status }'
{
"state_changes": [
{
"timestamp": "2022-05-18T13:34:17.967Z",
"old_state": "CHANNELD_NORMAL",
"new_state": "AWAITING_UNILATERAL",
"cause": "protocol",
"message": "Offered HTLC 102546 SENT_ADD_ACK_REVOCATION cltv 736923 hit deadline"
}
],
"status": [
"ONCHAIN:Tracking our own unilateral close",
"ONCHAIN:1 outputs unresolved: waiting confirmation that we spent OUR_HTLC (26…5e:0) using OUR_HTLC_TIMEOUT_TX"
]
}
{
"state_changes": [
{
"timestamp": "2021-12-04T12:19:07.794Z",
"old_state": "CHANNELD_NORMAL",
"new_state": "AWAITING_UNILATERAL",
"cause": "protocol",
"message": "Offered HTLC 7596 SENT_ADD_COMMIT cltv 712557 hit deadline"
}
],
"status": [
"ONCHAIN:Tracking our own unilateral close",
"ONCHAIN:1 outputs unresolved: waiting confirmation that we spent OUR_HTLC (c7…72:0) using OUR_HTLC_TIMEOUT_TX"
]
}
{
"state_changes": [
{
"timestamp": "2022-01-26T23:27:45.240Z",
"old_state": "CHANNELD_NORMAL",
"new_state": "AWAITING_UNILATERAL",
"cause": "protocol",
"message": "Offered HTLC 20804 SENT_ADD_ACK_REVOCATION cltv 720529 hit deadline"
}
],
"status": [
"ONCHAIN:Tracking our own unilateral close",
"ONCHAIN:1 outputs unresolved: waiting confirmation that we spent OUR_HTLC (0e…1e:0) using OUR_HTLC_TIMEOUT_TX"
]
}
{
"state_changes": [
{
"timestamp": "2022-05-21T18:35:23.566Z",
"old_state": "CHANNELD_NORMAL",
"new_state": "AWAITING_UNILATERAL",
"cause": "protocol",
"message": "Offered HTLC 16950 SENT_ADD_ACK_REVOCATION cltv 737330 hit deadline"
}
],
"status": [
"ONCHAIN:Tracking our own unilateral close",
"ONCHAIN:1 outputs unresolved: waiting confirmation that we spent OUR_HTLC (10…a5:0) using OUR_HTLC_TIMEOUT_TX"
]
}
{
"state_changes": [
{
"timestamp": "2022-03-01T23:15:04.553Z",
"old_state": "CHANNELD_NORMAL",
"new_state": "AWAITING_UNILATERAL",
"cause": "protocol",
"message": "Offered HTLC 556 SENT_ADD_ACK_REVOCATION cltv 725506 hit deadline"
}
],
"status": [
"ONCHAIN:Tracking our own unilateral close",
"ONCHAIN:1 outputs unresolved: waiting confirmation that we spent OUR_HTLC (63…5a:0) using OUR_HTLC_TIMEOUT_TX"
]
}
{
"state_changes": [
{
"timestamp": "2022-04-21T00:55:18.352Z",
"old_state": "CHANNELD_NORMAL",
"new_state": "AWAITING_UNILATERAL",
"cause": "protocol",
"message": "Offered HTLC 5841 SENT_ADD_ACK_REVOCATION cltv 732781 hit deadline"
}
],
"status": [
"ONCHAIN:Tracking our own unilateral close",
"ONCHAIN:1 outputs unresolved: waiting confirmation that we spent OUR_HTLC (23…9a:2) using OUR_HTLC_TIMEOUT_TX"
]
}
{
"state_changes": [
{
"timestamp": "2022-03-12T04:46:39.262Z",
"old_state": "CHANNELD_NORMAL",
"new_state": "AWAITING_UNILATERAL",
"cause": "protocol",
"message": "Offered HTLC 46357 SENT_ADD_ACK_REVOCATION cltv 726942 hit deadline"
}
],
"status": [
"ONCHAIN:Tracking our own unilateral close",
"ONCHAIN:1 outputs unresolved: waiting confirmation that we spent OUR_HTLC (7f…5b:1) using OUR_HTLC_TIMEOUT_TX"
]
}
{
"state_changes": [
{
"timestamp": "2022-04-10T16:23:05.176Z",
"old_state": "CHANNELD_NORMAL",
"new_state": "AWAITING_UNILATERAL",
"cause": "protocol",
"message": "Offered HTLC 2938 SENT_ADD_ACK_REVOCATION cltv 731285 hit deadline"
}
],
"status": [
"ONCHAIN:Tracking our own unilateral close",
"ONCHAIN:1 outputs unresolved: waiting confirmation that we spent OUR_HTLC (d3…87:0) using OUR_HTLC_TIMEOUT_TX"
]
}
Upon each new block that is added to the chain, CLN is rebroadcasting OUR_HTLC_TIMEOUT_TX. When Bitcoin Core replies that the transaction is already in the block chain, CLN isn't taking the hint.
What follows is an annotated (and redacted) transcript of the log messages pertaining to one channel (the 03…83 one that I reported about in my previous comment) through one full cycle of adding a new block. (All of these log messages repeat with each and every new block that is added.)
The first phase has lightningd firing off depth notifications to subdaemons:
2022-10-14T02:33:46.874Z DEBUG lightningd: Adding block 758563: 00…0f
2022-10-14T02:34:07.372Z DEBUG 03…83-chan#153256: Got depth change 46004->46005 for c7…72
2022-10-14T02:34:07.396Z DEBUG 03…83-chan#153256: Got depth change 44190->44191 for 22…d4
2022-10-14T02:34:07.419Z DEBUG 03…83-chan#153256: attempting update blockheight 82…3a
Next, onchaind receives the first depth change notification ("46004->46005 for c7…72"). This one is for the commitment transaction (OUR_UNILATERAL). Onchaind doesn't know that the OUR_HTLC output of the commitment transaction has already been claimed on chain, so it fires off a request to broadcast OUR_HTLC_TIMEOUT_TX to claim it. So far so good.
2022-10-14T02:34:33.474Z DEBUG 03…83-onchaind-chan#153256: Got new message WIRE_ONCHAIND_DEPTH
2022-10-14T02:34:34.094Z DEBUG 03…83-onchaind-chan#153256: FUNDING_TRANSACTION/FUNDING_OUTPUT->OUR_UNILATERAL depth 46005
2022-10-14T02:34:34.106Z DEBUG 03…83-onchaind-chan#153256: Broadcasting OUR_HTLC_TIMEOUT_TX (02…00) to resolve OUR_UNILATERAL/OUR_HTLC
2022-10-14T02:34:34.169Z DEBUG lightningd: Broadcasting txid f6…d6
2022-10-14T02:34:34.170Z DEBUG lightningd: sendrawtransaction: 02…00
2022-10-14T02:34:34.249Z DEBUG plugin-bcli: sendrawtx exit 27 (bitcoin-cli -datadir=/var/lib/bitcoind sendrawtransaction 02…00) error code: -27\nerror message:\nTransaction already in block chain
At this point, onchaind should realize something is up. Bitcoin Core replied that OUR_HTLC_TIMEOUT_TX is already in the block chain, but onchaind doesn't take notice of this.
There is also trivially the (non-delayed) output that pays out to the peer from the commitment transaction. We note it but don't care about it.
2022-10-14T02:34:34.273Z DEBUG 03…83-onchaind-chan#153256: OUR_UNILATERAL/OUTPUT_TO_THEM->SELF depth 46005
Now, onchaind notes that it is still awaiting confirmation of OUR_HTLC_TIMEOUT_TX, despite that Bitcoin Core just told it that the transaction is already in the block chain.
2022-10-14T02:34:34.299Z DEBUG 03…83-onchaind-chan#153256: billboard: 1 outputs unresolved: waiting confirmation that we spent OUR_HTLC (c7…72:0) using OUR_HTLC_TIMEOUT_TX
Lastly, onchaind receives the second depth change notification ("44190->44191 for 22…d4"). This one is for the return-to-wallet transaction that claims the delayed, non-HTLC output that pays out to us from the commitment transaction. Onchaind already knows that this transaction has confirmed, so it does nothing further here. And once again, onchaind helpfully mentions that it is still awaiting confirmation of OUR_HTLC_TIMEOUT_TX.
2022-10-14T02:34:38.199Z DEBUG 03…83-onchaind-chan#153256: Got new message WIRE_ONCHAIND_DEPTH
2022-10-14T02:34:38.245Z DEBUG 03…83-onchaind-chan#153256: OUR_UNILATERAL/DELAYED_OUTPUT_TO_US->OUR_DELAYED_RETURN_TO_WALLET depth 44191
2022-10-14T02:34:38.260Z DEBUG 03…83-onchaind-chan#153256: billboard: 1 outputs unresolved: waiting confirmation that we spent OUR_HTLC (c7…72:0) using OUR_HTLC_TIMEOUT_TX
And finally, we have some behavior that I can't explain. Lightningd broadcasts a conflicting version of the OUR_DELAYED_RETURN_TO_WALLET transaction four times, despite having noted above that OUR_DELAYED_RETURN_TO_WALLET is already at depth 44191.
2022-10-14T02:34:38.479Z DEBUG lightningd: sendrawtransaction: 02…00
2022-10-14T02:34:38.559Z DEBUG plugin-bcli: sendrawtx exit 25 (bitcoin-cli -datadir=/var/lib/bitcoind sendrawtransaction 02…00) error code: -25\nerror message:\nbad-txns-inputs-missingorspent
2022-10-14T02:34:38.565Z DEBUG lightningd: Expected error broadcasting tx 02…00: error code: -25\nerror message:\nbad-txns-inputs-missingorspent
2022-10-14T02:34:38.565Z DEBUG lightningd: sendrawtransaction: 02…00
2022-10-14T02:34:38.673Z DEBUG plugin-bcli: sendrawtx exit 25 (bitcoin-cli -datadir=/var/lib/bitcoind sendrawtransaction 02…00) error code: -25\nerror message:\nbad-txns-inputs-missingorspent
2022-10-14T02:34:38.680Z DEBUG lightningd: Expected error broadcasting tx 02…00: error code: -25\nerror message:\nbad-txns-inputs-missingorspent
2022-10-14T02:34:38.680Z DEBUG lightningd: sendrawtransaction: 02…00
2022-10-14T02:34:38.707Z DEBUG plugin-bcli: sendrawtx exit 25 (bitcoin-cli -datadir=/var/lib/bitcoind sendrawtransaction 02…00) error code: -25\nerror message:\nbad-txns-inputs-missingorspent
2022-10-14T02:34:38.713Z DEBUG lightningd: Expected error broadcasting tx 02…00: error code: -25\nerror message:\nbad-txns-inputs-missingorspent
2022-10-14T02:34:38.713Z DEBUG lightningd: sendrawtransaction: 02…00
2022-10-14T02:34:38.781Z DEBUG plugin-bcli: sendrawtx exit 25 (bitcoin-cli -datadir=/var/lib/bitcoind sendrawtransaction 02…00) error code: -25\nerror message:\nbad-txns-inputs-missingorspent
2022-10-14T02:34:38.787Z DEBUG lightningd: Expected error broadcasting tx 02…00: error code: -25\nerror message:\nbad-txns-inputs-missingorspent
The OUR_DELAYED_RETURN_TO_WALLET transaction that lightningd is spamming decodes as follows:
{
"txid": "10…ae",
"hash": "df…76",
"version": 2,
"size": 236,
"vsize": 121,
"weight": 482,
"locktime": 0,
"vin": [
{
"txid": "c7…72",
"vout": 2,
"scriptSig": {
"asm": "",
"hex": ""
},
"txinwitness": [
"30…01",
"",
"63…ac"
],
"sequence": 1802
}
],
"vout": [
{
"value": 0.07915610,
"n": 0,
"scriptPubKey": {
"asm": "0 10…ea",
"desc": "addr(bc1qz…3c)#…",
"hex": "00…ea",
"address": "bc1qz…3c",
"type": "witness_v0_keyhash"
}
}
]
}
…whereas the version of OUR_DELAYED_RETURN_TO_WALLET that is already in the block chain decodes as:
{
"txid": "22…d4",
"hash": "00…94",
"version": 2,
"size": 236,
"vsize": 121,
"weight": 482,
"locktime": 0,
"vin": [
{
"txid": "c7…72",
"vout": 2,
"scriptSig": {
"asm": "",
"hex": ""
},
"txinwitness": [
"30…01",
"",
"63…ac"
],
"sequence": 1802
}
],
"vout": [
{
"value": 0.07915623,
"n": 0,
"scriptPubKey": {
"asm": "0 10…ea",
"desc": "addr(bc1qz…3c)#…",
"hex": "00…ea",
"address": "bc1qz…3c",
"type": "witness_v0_keyhash"
}
}
]
}
The only difference between these two versions of OUR_DELAYED_RETURN_TO_WALLET (besides the signature) is that the one in the block chain pays 13 satoshis less in fees. I'm guessing that this is a red herring, though, since presumably the only reason lightningd is still making attempts to broadcast this at all is because it still hasn't resolved OUR_UNILATERAL/OUR_HTLC. Still, lightningd shouldn't be spamming Bitcoin Core with OUR_DELAYED_RETURN_TO_WALLET when it knows it already has an equivalent transaction confirmed, so I'd consider this a separate (minor) bug.
The bottom line: How can we get onchaind to understand that the OUR_HTLC_TIMEOUT_TX that it's been trying to broadcast for months (and feverishly spams for hours upon every node startup) has in fact already confirmed?
I was finally able to sort this out for myself. As it turns out, the missing spends were in fact present in the transactions table but were missing from the channeltxs table. Thus, at startup some WIRE_ONCHAIND_SPENT messages were not being replayed to onchaind. I manually inserted the missing type=5004 (WIRE_ONCHAIND_SPENT) records into channeltxs and restarted my node, and immediately it spent the outputs of all of the OUR_HTLC_TIMEOUT_TX transactions that it previously had been ignoring for months.
As a side note, my channeltxs table contained hundreds of thousands of type=5005 (WIRE_ONCHAIND_DEPTH) records for the stuck channels. I deleted all but the latest (greatest blockheight) for each of the stuck channels before restarting my node. The node startup then was much faster, and lightningd is using less than 400 MB of RAM, whereas previously it would immediately shoot up past 5 GB and stay there, and I'm not seeing the storm of "Transaction already in block chain" errors.
As for how my database got into this state, I have a question: when lightningd fires a notification of a spend of a watched TxO, are the relevant records added to the transactions and channeltxs tables in a single transaction? If they're separate transactions, then a kill of the lightningd process between the transactions would leave the database in the state that I observed, with channels forever stuck.