'dev-forget-channel' on channel in state ONCHAIND_THEIR_UNILATERAL crashes lightningd

[sfmcnally]

pi@raspberrypi ~ $lightning-cli listpeers
{ "peers" :
[
{ "id" : "02f6725f9c1c40333b67faea92fd211c183050f28df32cac3f9d69685fe9665432", "connected" : true, "netaddr" :
[ "104.198.32.198:9735" ], "channels" :
[
{ "state" : "CHANNELD_NORMAL", "owner" : "lightning_channeld", "short_channel_id" : "507492:1465:1", "funding_txid" : "bcaadfbadc0e072de11588c3164a75a5cdccd5a20a46ed77bbaddc7c4d25fff1", "msatoshi_to_us" : 44991075, "msatoshi_total" : 100002000, "dust_limit_satoshis" : 546, "max_htlc_value_in_flight_msat" : 18446744073709551615, "channel_reserve_satoshis" : 0, "htlc_minimum_msat" : 0, "to_self_delay" : 144, "max_accepted_htlcs" : 483 } ] },
{ "id" : "035f1498c929d4cefba4701ae36a554691f526ff60b1766badd5a49b3c8b68e1d8", "connected" : true, "netaddr" :
[ "78.63.23.25:9735" ], "channels" :
[
{ "state" : "CHANNELD_NORMAL", "owner" : "lightning_channeld", "short_channel_id" : "507147:1263:1", "funding_txid" : "943203a3f4678456bdc34a54ab80e4896368362b6a74b3a1a478b8f0fda34e51", "msatoshi_to_us" : 100001000, "msatoshi_total" : 100001000, "dust_limit_satoshis" : 546, "max_htlc_value_in_flight_msat" : 18446744073709551615, "channel_reserve_satoshis" : 0, "htlc_minimum_msat" : 0, "to_self_delay" : 144, "max_accepted_htlcs" : 483 } ] },
{ "id" : "02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083", "connected" : false, "channels" :
[
{ "state" : "ONCHAIND_THEIR_UNILATERAL", "short_channel_id" : "507123:1172:1", "funding_txid" : "144698a9c2e0a3106f3d9b9de53143647f0fd282377cea438756a368a7f2a858", "msatoshi_to_us" : 150000000, "msatoshi_total" : 150000000, "dust_limit_satoshis" : 546, "max_htlc_value_in_flight_msat" : 18446744073709551615, "channel_reserve_satoshis" : 0, "htlc_minimum_msat" : 0, "to_self_delay" : 144, "max_accepted_htlcs" : 483 } ] },
{ "id" : "029efce538a7f6ba7873b1bd00e0028ca39a658b96af326d349fa45bfa34226073", "connected" : false, "channels" :
[
{ "state" : "CHANNELD_NORMAL", "short_channel_id" : "506897:1628:1", "funding_txid" : "958ca3ab5680972286ce2d7dce72583fb590fd373a2c34b997f291da234ac4c6", "msatoshi_to_us" : 100000000, "msatoshi_total" : 100000000, "dust_limit_satoshis" : 546, "max_htlc_value_in_flight_msat" : 18446744073709551615, "channel_reserve_satoshis" : 0, "htlc_minimum_msat" : 0, "to_self_delay" : 144, "max_accepted_htlcs" : 483 } ] } ] }

pi@raspberrypi ~ $ lightning-cli dev-forget-channel 02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083
lightning-cli: reading response: Success

pi@raspberrypi ~ $ lightning-cli listpeers
lightning-cli: Connecting to 'lightning-rpc': Connection refused

[sfmcnally]

'dev-forget-channel' did work correctly for a channel in state CHANNELD_AWAITING_LOCKIN

pi@raspberrypi ~ $ lightning-cli dev-forget-channel 031c527494f295220d26a1814c18e7db3f4f03203ce1a53a0b74b52ed570a3972a
{ "forced" : false, "funding_unspent" : false, "funding_txid" : "c4092b5757099739e2dfeee9da736d634ea4989cc21ac8cb5a8e4b464dec3ae2" }

[cdecker]

Could you please provide the log output?

[sfmcnally]

getlog doesn't return any info other than the startup info. Is there another location for a more detailed log?

[cdecker]

You could redirect the daemon output to a file using the following:

lightningd/lightningd --log-level=debug | tee logfile.log

and then reattempt the dev-forget-channel. That'll create a logfile.log which you can paste to https://gist.github.com/

[sfmcnally]

crash.log

[sfmcnally]

this was in my ./lightning folder after I reproduced the issue. let me know if you want me to redirect manually and I will.

[cdecker]

Sadly that crash log does not include a backtrace. Could you try with the log?

[sfmcnally]

Here you go. It reports "success" just before crashing.
logfile.log

[cdecker]

I tried to replicate the issue, and I'm unable to do so. Could you maybe run the crashing instance in gdb, e.g., with the following command:

gdb lightningd/lightningd -ex 'r --log-level=debug'

That should intercept the crash and put you in a debug shell. I'd need a backtrace from you, the command bt will print that, and you can copy-paste it. If this is on testnet could you also provide a core-dump? You can create one with generate-core-file (caution: the core dump may contain your secret key so only do this on testnet). And I'll also need the output of lightning-cli getinfo to know which commit you're running so I can load the core-dump.

[sfmcnally]

here's the backtrace, but I was playing on mainnet, so I didn't include the core-dump. If you want that privately, I can work on that when I have time.

#0  0x76cbcf70 in __GI_raise (sig=sig@entry=6)
    at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1  0x76cbe324 in __GI_abort () at abort.c:89
#2  0x00020e54 in fatal (fmt=0xc6b18 "Freeing peer %s has hout %s")
    at lightningd/log.c:575
#3  0x000285c4 in destroy_peer (peer=0x11dcb0) at lightningd/peer_control.c:107
#4  0x00083cc8 in notify (ctx=0x11dca0, type=TAL_NOTIFY_FREE, info=0x11dcb0, 
    saved_errno=2) at ccan/ccan/tal/tal.c:240
#5  0x00084288 in del_tree (t=0x11dca0, orig=0x11dcb0, saved_errno=2)
    at ccan/ccan/tal/tal.c:400
#6  0x0008478c in tal_free (ctx=0x11dcb0) at ccan/ccan/tal/tal.c:509
#7  0x00028970 in free_peer (peer=0x11dcb0, 
    why=0xc8bd8 "dev-forget-channel called") at lightningd/peer_control.c:184
#8  0x00030888 in process_dev_forget_channel (bitcoind=0xf9490, txout=0x0, 
    arg=0x788f60) at lightningd/peer_control.c:2982
#9  0x00013f58 in process_gettxout (bcli=0x57d658) at lightningd/bitcoind.c:469
#10 0x00013248 in bcli_finished (conn=0x98ce40, bcli=0x57d658)
    at lightningd/bitcoind.c:173
#11 0x0007785c in destroy_conn (conn=0x98ce40, close_fd=true)
    at ccan/ccan/io/poll.c:183
#12 0x00077884 in destroy_conn_close_fd (conn=0x98ce40)
    at ccan/ccan/io/poll.c:189
#13 0x00083cc8 in notify (ctx=0x98ce30, type=TAL_NOTIFY_FREE, info=0x98ce40, 
    saved_errno=9) at ccan/ccan/tal/tal.c:240
#14 0x00084288 in del_tree (t=0x98ce30, orig=0x98ce40, saved_errno=9)
    at ccan/ccan/tal/tal.c:400
#15 0x0008478c in tal_free (ctx=0x98ce40) at ccan/ccan/tal/tal.c:509
#16 0x00075ec8 in io_close (conn=0x98ce40) at ccan/ccan/io/io.c:443
#17 0x00077d78 in io_loop (timers=0xf9150, expired=0x7efff560)
    at ccan/ccan/io/poll.c:314
#18 0x0001f044 in main (argc=4, argv=0x7efff6e4) at lightningd/lightningd.c:352

[cdecker]

Oh, I see, you had an HTLC in flight while the channel was closing, that's ugly. dev-forget-channel is definitely not intended to forget those channels, since you still have some funds that you are negotiating with the peer. Strange that it still hasn't cleared. Do you have a lightning_onchaind process running when starting lightningd? That should clean up and close the channel in the end.

I can add a safeguard to fail the command if we have HTLCs in flight, so that at least we don't crash anymore.

[sfmcnally]

I made sure the blockchain was up to date and then I tried again. Here is what I got:

lightning-cli dev-forget-channel 02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083
lightning-cli: reading response: Success
pi@raspberrypi ~ $ lightning-cli listpeers
lightning-cli: Connecting to 'lightning-rpc': Connection refused

It crashed again. The ONCHAIN_UNILATERAL_THEIRS is a week old. It should have completed by now. I'll try a dev-rescan-outputs and then try again.

[cdecker]

Ok, it seems that the channel was closed successfully despite having an HTLC attached to it (payment went through apparently). We definitely need to clean up those channels as well. I'll add a check for HTLCs, so I'll add a check and clear HTLCs when forced.

[sfmcnally]

Thanks. I'll be happy to test it when you are ready.

[cdecker]

Just as a quick update, we opted not to merge #987 since using dev-forget-channel is masking the error instead of fixing it. By giving a workaround we'd be encouraging users to not report issues and we would not be able to fix the root cause. I'll create a tiny patch that just fails the JSON-RPC call, instead of crashing to address this issue here.