triggerforceclose not working... any way to debug?

[sudocarlos]

I am trying to trigger a force close to a CLN peer because I think I am experiencing the issue described in https://github.com/lightninglabs/chantools/blob/master/doc/chantools_triggerforceclose.md

in case the peer is a specific version of CLN that does not properly respond to a Data Loss Protection re-establish message

It looks like even this isn't working and I haven't been able to get in contact with the peer. This is an unannounced channel, not sure if that makes a difference. Is there any way to further debug this?

lnd:~# chantools triggerforceclose  --peer 037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138@jg7tka7hxo4tzqlwom56urpeuhdxn4bya73egflw6xcwki2tddcsuaid.onion:9735  --channel_point ***  --rootkey ***  --torproxy $(ip route | grep default | awk '{print $3}'):9050
2024-07-27 12:41:48.899 [INF] CHAN: chantools version v0.13.1 commit 
2024-07-27 12:41:48.900 [DBG] CHAN: Attempting to resolve peer address 037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138@jg7tka7hxo4tzqlwom56urpeuhdxn4bya73egflw6xcwki2tddcsuaid.onion:9735
2024-07-27 12:41:48.901 [DBG] CHAN: Attempting to dial resolved peer address 037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138@jg7tka7hxo4tzqlwom56urpeuhdxn4bya73egflw6xcwki2tddcsuaid.onion:9735
2024-07-27 12:41:52.140 [INF] CHAN: Attempting to establish p2p connection to peer 02d523cf57a7736d04db04b76076badb2d4b81a4cfe6fe16114aee2f500cef845d, dialtimeout is 1m0s
2024-07-27 12:41:52.152 [DBG] CHDB: Populating in-memory channel graph, this might take a while...
2024-07-27 12:41:52.152 [DBG] CHDB: Finished populating in-memory channel graph (took 479.989µs, num_node_features=0, num_nodes=0, num_channels=0)
2024-07-27 12:41:52.152 [INF] CHDB: Checking for schema update: latest_version=31, db_version=31
2024-07-27 12:41:52.153 [INF] CHDB: Checking for optional update: prune_revocation_log=false, db_version=empty
2024-07-27 12:41:52.153 [DBG] PEER: Peer(037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138): Sending Init to 037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138@jg7tka7hxo4tzqlwom56urpeuhdxn4bya73egflw6xcwki2tddcsuaid.onion:9735
2024-07-27 12:41:52.796 [DBG] PEER: Peer(037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138): Received Init from 037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138@jg7tka7hxo4tzqlwom56urpeuhdxn4bya73egflw6xcwki2tddcsuaid.onion:9735
2024-07-27 12:41:52.796 [DBG] PEER: Peer(037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138): Loaded 0 active channels from database
2024-07-27 12:41:52.796 [INF] CHAN: Connection established to peer 02d523cf57a7736d04db04b76076badb2d4b81a4cfe6fe16114aee2f500cef845d
2024-07-27 12:41:52.796 [INF] CHAN: Sending channel re-establish to peer to trigger force close of channel ***
2024-07-27 12:41:52.797 [DBG] PEER: Peer(037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138): Sending ChannelReestablish(chan_id=08c9d1f07af7b677f86d95b9574862e38ad224afcbd5f64c2a3e91edf96969d2, next_local_height=0, remote_tail_height=0) to 037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138@jg7tka7hxo4tzqlwom56urpeuhdxn4bya73egflw6xcwki2tddcsuaid.onion:9735
2024-07-27 12:41:52.797 [INF] CHAN: Sending channel error message to peer to trigger force close of channel ***
2024-07-27 12:41:52.797 [INF] PEER: Peer(037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138): Negotiated chan series queries
2024-07-27 12:41:52.797 [DBG] PEER: Peer(037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138): Sending Error(type=17) to 037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138@jg7tka7hxo4tzqlwom56urpeuhdxn4bya73egflw6xcwki2tddcsuaid.onion:9735
2024-07-27 12:41:52.798 [INF] CHAN: Message sent, waiting for force close transaction to appear in mempool
2024-07-27 12:42:08.047 [INF] CHAN: No spends found yet, waiting 5 seconds...
2024-07-27 12:42:13.138 [INF] CHAN: No spends found yet, waiting 5 seconds...
2024-07-27 12:42:22.709 [INF] CHAN: No spends found yet, waiting 5 seconds...
2024-07-27 12:42:31.743 [INF] CHAN: No spends found yet, waiting 5 seconds...
2024-07-27 12:42:38.219 [INF] CHAN: No spends found yet, waiting 5 seconds...
2024-07-27 12:42:47.613 [INF] CHAN: No spends found yet, waiting 5 seconds...
2024-07-27 12:42:52.798 [DBG] PEER: Peer(037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138): Sending Ping(ping_bytes=0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000) to 037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138@jg7tka7hxo4tzqlwom56urpeuhdxn4bya73egflw6xcwki2tddcsuaid.onion:9735
2024-07-27 12:42:52.798 [INF] PEER: Peer(037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138): disconnecting 037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138@jg7tka7hxo4tzqlwom56urpeuhdxn4bya73egflw6xcwki2tddcsuaid.onion:9735, reason: unable to write message: write tcp 172.18.0.232:54120->172.18.0.1:9050: write: broken pipe
2024-07-27 12:42:55.675 [INF] CHAN: No spends found yet, waiting 5 seconds...
2024-07-27 12:43:07.793 [INF] CHAN: No spends found yet, waiting 5 seconds...
2024-07-27 12:43:14.686 [INF] CHAN: No spends found yet, waiting 5 seconds...

[guggero]

From the logs, it looks like both the generic (lnd compatible) message (Sending ChannelReestablish) and the CLN specific (Sending Error(type=17)) message is being sent. So if the node is aware of the channel, it should publish the force close transaction.

Just to rule out that the generic, first message doesn't throw off the node, can you try again with the triggerforceclose-cln branch? (commit f8c6661).

[sudocarlos]

Thanks for the quick update, same result.

root@89f22c69e6a6:/go/chantools# chantools triggerforceclose \
 --peer 037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138@jg7tka7hxo4tzqlwom56urpeuhdxn4bya73egflw6xcwki2tddcsuaid.onion:9735 \
 --channel_point *** \
 --rootkey *** \
 --torproxy 172.18.0.1:9050
2024-07-29 17:28:10.886 [INF] CHAN: chantools version v0.13.1 commit 
2024-07-29 17:28:10.886 [DBG] CHAN: Attempting to resolve peer address 037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138@jg7tka7hxo4tzqlwom56urpeuhdxn4bya73egflw6xcwki2tddcsuaid.onion:9735
2024-07-29 17:28:10.886 [DBG] CHAN: Attempting to dial resolved peer address 037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138@jg7tka7hxo4tzqlwom56urpeuhdxn4bya73egflw6xcwki2tddcsuaid.onion:9735
2024-07-29 17:28:13.140 [INF] CHAN: Attempting to establish p2p connection to peer 02d523cf57a7736d04db04b76076badb2d4b81a4cfe6fe16114aee2f500cef845d, dialtimeout is 1m0s
2024-07-29 17:28:13.145 [DBG] CHDB: Populating in-memory channel graph, this might take a while...
2024-07-29 17:28:13.145 [DBG] CHDB: Finished populating in-memory channel graph (took 786.955µs, num_node_features=0, num_nodes=0, num_channels=0)
2024-07-29 17:28:13.146 [INF] CHDB: Checking for schema update: latest_version=31, db_version=31
2024-07-29 17:28:13.146 [INF] CHDB: Checking for optional update: prune_revocation_log=false, db_version=empty
2024-07-29 17:28:13.146 [DBG] PEER: Peer(037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138): Sending Init to 037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138@jg7tka7hxo4tzqlwom56urpeuhdxn4bya73egflw6xcwki2tddcsuaid.onion:9735
2024-07-29 17:28:13.486 [DBG] PEER: Peer(037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138): Received Init from 037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138@jg7tka7hxo4tzqlwom56urpeuhdxn4bya73egflw6xcwki2tddcsuaid.onion:9735
2024-07-29 17:28:13.486 [DBG] PEER: Peer(037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138): Loaded 0 active channels from database
2024-07-29 17:28:13.486 [INF] CHAN: Connection established to peer 02d523cf57a7736d04db04b76076badb2d4b81a4cfe6fe16114aee2f500cef845d
2024-07-29 17:28:13.486 [INF] CHAN: Sending channel error message to peer to trigger force close of channel ***
2024-07-29 17:28:13.486 [DBG] PEER: Peer(037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138): Sending Error(type=17) to 037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138@jg7tka7hxo4tzqlwom56urpeuhdxn4bya73egflw6xcwki2tddcsuaid.onion:9735
2024-07-29 17:28:13.486 [INF] CHAN: Message sent, waiting for force close transaction to appear in mempool
2024-07-29 17:28:13.486 [INF] PEER: Peer(037a43b480b33ffaaaef6abd80814becfb89389c21bd18787884e186a5cb507138): Negotiated chan series queries
2024-07-29 17:28:37.466 [INF] CHAN: No spends found yet, waiting 5 seconds...
2024-07-29 17:28:50.946 [INF] CHAN: No spends found yet, waiting 5 seconds...
2024-07-29 17:29:00.793 [INF] CHAN: No spends found yet, waiting 5 seconds...
2024-07-29 17:29:07.624 [INF] CHAN: No spends found yet, waiting 5 seconds...
2024-07-29 17:29:13.470 [INF] CHAN: No spends found yet, waiting 5 seconds...
2024-07-29 17:29:22.661 [INF] CHAN: No spends found yet, waiting 5 seconds...
2024-07-29 17:29:34.499 [INF] CHAN: No spends found yet, waiting 5 seconds...
2024-07-29 17:29:40.512 [INF] CHAN: No spends found yet, waiting 5 seconds...
2024-07-29 17:29:49.933 [INF] CHAN: No spends found yet, waiting 5 seconds...
2024-07-29 17:29:59.920 [INF] CHAN: No spends found yet, waiting 5 seconds...
2024-07-29 17:30:11.363 [INF] CHAN: No spends found yet, waiting 5 seconds...
2024-07-29 17:30:21.437 [INF] CHAN: No spends found yet, waiting 5 seconds...
2024-07-29 17:30:29.423 [INF] CHAN: No spends found yet, waiting 5 seconds...
2024-07-29 17:30:42.318 [INF] CHAN: No spends found yet, waiting 5 seconds...
2024-07-29 17:30:49.391 [INF] CHAN: No spends found yet, waiting 5 seconds...
2024-07-29 17:30:58.238 [INF] CHAN: No spends found yet, waiting 5 seconds...
2024-07-29 17:31:06.470 [INF] CHAN: No spends found yet, waiting 5 seconds...
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x18 pc=0x123d049]

goroutine 13 [running]:
github.com/lightningnetwork/lnd/peer.NewBrontide.func1()
	/go/pkg/mod/github.com/lightningnetwork/lnd@v0.18.0-beta.1/peer/brontide.go:576 +0x29
github.com/lightningnetwork/lnd/peer.(*PingManager).pingHandler(0xc0000d20e0)
	/go/pkg/mod/github.com/lightningnetwork/lnd@v0.18.0-beta.1/peer/ping_manager.go:141 +0x1ca
created by github.com/lightningnetwork/lnd/peer.(*PingManager).Start.func1 in goroutine 1
	/go/pkg/mod/github.com/lightningnetwork/lnd@v0.18.0-beta.1/peer/ping_manager.go:105 +0xcc

[guggero]

Thanks for trying that out... Then it seems like the node definitely doesn't want to force close. Or maybe they do but the transaction for some reason doesn't reach any connected mempool?
Was the channel ever fully operational? Or did it take too long (more than 2 weeks) to confirm initially?

[sudocarlos]

The channel was fully operational for almost a year. Not sure how much was transacted on it. It is an unannounced channel and I'm not sure how long it took to mine/confirm the transaction. mempool.space shows 'Not seen in Mempool' but it was a 50 sat/vb transaction! 😭 My own mempool instance doesn't have more info about the transaction.

[guggero]

Hmm, so you're saying the transaction of the channel point isn't in the blockchain? Can you DM me the channel point please? Either on Slack or e-mail (see my profile)?