search

ElementsProject / lightning

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

fundchannel fails with lnd node #4238

Closed evd0kim closed 3 years ago

evd0kim commented 3 years ago

Issue and Steps to Reproduce

I'm trying to open a channel with

fundchannel 029dd81c32e3ea839b4b2f8edcc9bea227c40fa2c6509878034401a8ce2a8bac05 all fast true 0 [TXID:N]

And I get an error which I do not understand.

lightning-cli: Incorrect 'id' in response: null

getinfo output

{
   "id": "ID",
   "alias": "test",
   "color": "ff0000",
   "num_peers": 10,
   "num_pending_channels": 1,
   "num_active_channels": 6,
   "num_inactive_channels": 1,
   "address": [
      {
         "type": "ipv4",
         "address": "46.101.127.98",
         "port": 51486
      }
   ],
   "binding": [
      {
         "type": "ipv4",
         "address": "0.0.0.0",
         "port": 51486
      }
   ],
   "version": "v0.9.2",
   "blockheight": 659508,
   "network": "bitcoin",
   "msatoshi_fees_collected": 16029,
   "fees_collected_msat": "16029msat",
   "lightning-dir": "/home/lnadmin/.lightning/bitcoin"
}
ZmnSCPxj commented 3 years ago

Huh. This is an error which "should not" happen. Can you provide logs?

We use the term "urgent" rather than "fast" for feerates, so it seems likely to me that the problem is triggered by this. But it should lead to a -32602 parameter error, not a id null.

evd0kim commented 3 years ago

@ZmnSCPxj thank you for your response.

I tried 

clg-cli fundchannel 029dd81c32e3ea839b4b2f8edcc9bea227c40fa2c6509878034401a8ce2a8bac05 all urgent true 0 [TXID:1]

with the result

lightning-cli: Incorrect 'id' in response: null
evd0kim commented 3 years ago

This is what i have in logs

2020-12-02T08:12:45.581Z DEBUG   029dd81c32e3ea839b4b2f8edcc9bea227c40fa2c6509878034401a8ce2a8bac05-connectd: Connected out, starting crypto
2020-12-02T08:12:45.632Z DEBUG   029dd81c32e3ea839b4b2f8edcc9bea227c40fa2c6509878034401a8ce2a8bac05-connectd: Connect OUT
2020-12-02T08:12:45.632Z DEBUG   029dd81c32e3ea839b4b2f8edcc9bea227c40fa2c6509878034401a8ce2a8bac05-connectd: peer_out WIRE_INIT
2020-12-02T08:12:45.676Z DEBUG   029dd81c32e3ea839b4b2f8edcc9bea227c40fa2c6509878034401a8ce2a8bac05-connectd: peer_in WIRE_INIT
2020-12-02T08:12:45.676Z DEBUG   029dd81c32e3ea839b4b2f8edcc9bea227c40fa2c6509878034401a8ce2a8bac05-gossipd: seeker: disabling gossip
2020-12-02T08:12:45.679Z DEBUG   029dd81c32e3ea839b4b2f8edcc9bea227c40fa2c6509878034401a8ce2a8bac05-openingd-chan#4078: pid 8328, msgfd 59
2020-12-02T08:12:45.694Z DEBUG   029dd81c32e3ea839b4b2f8edcc9bea227c40fa2c6509878034401a8ce2a8bac05-openingd-chan#4078: Handed peer, entering loop
2020-12-02T08:12:45.695Z DEBUG   029dd81c32e3ea839b4b2f8edcc9bea227c40fa2c6509878034401a8ce2a8bac05-openingd-chan#4078: peer_out WIRE_GOSSIP_TIMESTAMP_FILTER

getlog is pretty silent about tried node.

ZmnSCPxj commented 3 years ago

Can you enable --log-level=debug:spenderp and show logs from plugin-spenderp?

evd0kim commented 3 years ago

@ZmnSCPxj I will look into this plugin and I will try to do that.

evd0kim commented 3 years ago

Does it help you @ZmnSCPxj ?

2020-11-30T15:40:25.683Z INFO    plugin-spenderp: Killing plugin: Could not register method "multiwithdraw", a method with that name is already registered
2020-11-30T17:30:42.186Z DEBUG   plugin-spenderp: mfc 467: multiconnect.
2020-11-30T17:30:42.186Z DEBUG   plugin-spenderp: mfc 467, dest 0: connect 029dd81c32e3ea839b4b2f8edcc9bea227c40fa2c6509878034401a8ce2a8bac05.
2020-11-30T17:30:42.338Z DEBUG   plugin-spenderp: mfc 467, dest 0: connect done.
2020-11-30T17:30:42.338Z DEBUG   plugin-spenderp: mfc 467: multiconnect done.
2020-11-30T17:30:42.338Z DEBUG   plugin-spenderp: mfc 467: utxopsbt.
2020-11-30T17:30:42.339Z DEBUG   plugin-spenderp: mfc 467: forwarding error, about to cleanup.
2020-11-30T17:30:42.339Z DEBUG   plugin-spenderp: mfc 467: cleanup!
2020-11-30T17:30:42.339Z DEBUG   plugin-spenderp: mfc 467: cleanup done, failing raw.
2020-11-30T17:34:57.873Z DEBUG   plugin-spenderp: mfc 486: multiconnect.
2020-11-30T17:34:57.873Z DEBUG   plugin-spenderp: mfc 486, dest 0: connect 029dd81c32e3ea839b4b2f8edcc9bea227c40fa2c6509878034401a8ce2a8bac05.
2020-11-30T17:34:57.873Z DEBUG   plugin-spenderp: mfc 486, dest 0: connect done.
2020-11-30T17:34:57.873Z DEBUG   plugin-spenderp: mfc 486: multiconnect done.
2020-11-30T17:34:57.873Z DEBUG   plugin-spenderp: mfc 486: utxopsbt.
2020-11-30T17:34:57.873Z DEBUG   plugin-spenderp: mfc 486: forwarding error, about to cleanup.
2020-11-30T17:34:57.873Z DEBUG   plugin-spenderp: mfc 486: cleanup!
2020-11-30T17:34:57.873Z DEBUG   plugin-spenderp: mfc 486: cleanup done, failing raw.
2020-12-01T17:19:35.531Z INFO    plugin-spenderp: Killing plugin: Could not register method "multiwithdraw", a method with that name is already registered
2020-12-02T14:13:48.796Z INFO    plugin-spenderp: Killing plugin: Could not register method "multiwithdraw", a method with that name is already registered
2020-12-02T14:14:00.726Z INFO    plugin-spenderp: Killing plugin: Could not register method "multiwithdraw", a method with that name is already registered
2020-12-02T14:14:11.543Z INFO    plugin-spenderp: Killing plugin: Could not register method "multiwithdraw", a method with that name is already registered
2020-12-02T14:14:22.252Z INFO    plugin-spenderp: Killing plugin: Could not register method "multiwithdraw", a method with that name is already registered
2020-12-02T14:14:33.012Z INFO    plugin-spenderp: Killing plugin: Could not register method "multiwithdraw", a method with that name is already registered
2020-12-02T14:14:44.515Z INFO    plugin-spenderp: Killing plugin: Could not register method "multiwithdraw", a method with that name is already registered
2020-12-02T16:10:25.215Z INFO    plugin-spenderp: Killing plugin: Could not register method "multiwithdraw", a method with that name is already registered
ZmnSCPxj commented 3 years ago

There is something fairly strange with your setup, with multiple spenderp apparently getting run.

On the other hand, id of null should basically never happen normally. What exactly is clg-cli, and what does it expand to?

evd0kim commented 3 years ago

@ZmnSCPxj that's an alias

lightning-cli --lightning-dir /home/lnadmin/.lightning/

evd0kim commented 3 years ago

Your suggestion reminded me to check my setup and I indeed have specified plugin dir in config. But for a strange reason systems service accepts only the default path. I tried it multiple times. I will try to remove path from config.

evd0kim commented 3 years ago

@ZmnSCPxj Ok. I figured that out that lightning always load "important" plugins from /usr/local/libexec/c-lightning/ while some optional user plugins loaded from additional plugin dir. I always thought there is only a single place for plugins. Now it makes sense that Fiatjaf once noticed that /usr/local/libexec/c-lightning/plugins must be cleaned.

Now, plugin-spenderp is working. Maybe all bugs magically disappear then.

ZmnSCPxj commented 3 years ago

No more issues with fundchannel?

evd0kim commented 3 years ago

I've not tested it yet. If you know a recipe for how to abandon not opened channel I can test it faster. There is an important for me peer with which I can't open a channel. The transaction failed to broadcast, and I ended up with this AWAITING_UNILATERAL state for days.

{
   "code": -1,
   "message": "Channel is in state AWAITING_UNILATERAL"
}
ZmnSCPxj commented 3 years ago

Ideally, we should really double-spend the funding transaction and force the outputs it spent to be re-spent on an urgent transaction to pay to ourselves. I am uncertain about the coin reservation logic, try checking with @niftynei or @rustyrussell first.

If you are sure that nobody else has a copy of the funding/unilteral-close transaction (a random wog could just keep a copy and broadcast it later during a low-fee period, this is always a risk with onchain, which is why you should really avoid slow feerate unless you have provision for later CPFP at higher than urgent), and you configured with ./configure --enable-developer, then a dev-forget-channel command exists. This is dangerous and only do this if you are 100% definitely sure the funding/unilateral-close transaction never left your device (you probably are not).

evd0kim commented 3 years ago

It looks like it is exactly what I need. Thank you very much @ZmnSCPxj, you are a legend. I will come back with the results later.

evd0kim commented 3 years ago

@ZmnSCPxj thank you for the hint. The channel disappeared from my DB finally. But I can't create a new channel anyway. I see again lightning-cli: Incorrect 'id' in response: null. Please, ask about io dump Christian.

ZmnSCPxj commented 3 years ago

Only occurs for fundchannel? How about listpays? The plugin-spenderp logs show the same result?

evd0kim commented 3 years ago

@ZmnSCPxj listpays works fine. I stopped io log dump since it hurts VPS can't say anything about plugin.

I've tried to track problem with "non-matching" cli as suggested by Christian and pointed alias to build directory but the results are the same. By the way can you provide me with example of fundchannel command with UTXO selection which is works for you 1000%?

cdecker commented 3 years ago

Turns out it was a malformed parameter from the shell being inserted verbatim into the JSON-RPC request, and thus failing the parser in lightningd. Not being able to parse the request, lightningd cannot return an error since it doesn't have the id. As indicated by the JSON-RPC spec we returned an error with id=null, which then resulted in lightning-cli being unable to associate it with the request.

See #4259 for a fix: we now parse the request in lightning-cli before sending it to lightningd to make sure the construction doesn't result in malformed JSON messages.