Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

New channel with ACQIN is not active #4575

Closed
manreo opened this issue Aug 29, 2020 · 34 comments
Closed

New channel with ACQIN is not active #4575

manreo opened this issue Aug 29, 2020 · 34 comments
Assignees
Labels
p2p Code related to the peer-to-peer behaviour server

Comments

@manreo
Copy link
Contributor

manreo commented Aug 29, 2020

Background

I tried to open a channel with ACQIN node and for some reason the channel is inactive. I do not know why, I can ping the ip address, but the channel remains inactive.
This is the command that I used to open the channel (It is in the history of the terminal:
lncli openchannel 03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f 4500000 --sat_per_byte 1

Logs

Channel info

        {
            "active": false,
            "remote_pubkey": "03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f",
            "channel_point": "fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1",
            "chan_id": "709134422426189825",
            "capacity": "4500000",
            "local_balance": "4477856",
            "remote_balance": "0",
            "commit_fee": "22144",
            "commit_weight": "600",
            "fee_per_kw": "30586",
            "unsettled_balance": "0",
            "total_satoshis_sent": "0",
            "total_satoshis_received": "0",
            "num_updates": "0",
            "pending_htlcs": [
            ],
            "csv_delay": 720,
            "private": false,
            "initiator": true,
            "chan_status_flags": "ChanStatusDefault",
            "local_chan_reserve_sat": "45000",
            "remote_chan_reserve_sat": "45000",
            "static_remote_key": false,
            "commitment_type": "LEGACY",
            "lifetime": "29761",
            "uptime": "29636",
            "close_address": "",
            "push_amount_sat": "0",
            "thaw_height": 0,
            "local_constraints": {
                "csv_delay": 720,
                "chan_reserve_sat": "45000",
                "dust_limit_sat": "573",
                "max_pending_amt_msat": "20000000000",
                "min_htlc_msat": "1",
                "max_accepted_htlcs": 30
            },
            "remote_constraints": {
                "csv_delay": 540,
                "chan_reserve_sat": "45000",
                "dust_limit_sat": "546",
                "max_pending_amt_msat": "4455000000",
                "min_htlc_msat": "1",
                "max_accepted_htlcs": 483
            }
        },

Related logs:

2020-08-18 14:10:47.304 [INF] CNCT: Creating new ChannelArbitrator for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1)
2020-08-18 14:10:47.310 [INF] CNCT: ChannelArbitrator(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1): starting state=StateDefault, trigger=chainTrigger, triggerHeight=644278
2020-08-18 14:10:47.310 [INF] NTFN: New spend subscription: spend_id=70, outpoint=fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1, script=0 6e52b92e00d423495dcfd2702f1598c637363a0ced0450deef37b83a941937d9, height_hint=644278
2020-08-18 14:10:47.310 [INF] NTFN: Dispatching historical spend rescan for outpoint=fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1, script=0 6e52b92e00d423495dcfd2702f1598c637363a0ced0450deef37b83a941937d9, start=644278, end=644278
2020-08-18 14:10:47.409 [INF] FNDG: Finalizing pending_id(35f3ea5996ea9db81d6f417bbe18d4ad660903077fa9d01a53c12f1cfa8d6e4b) over ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1), waiting for channel open on-chain
2020-08-18 14:10:47.410 [INF] CNCT: Close observer for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1) active
2020-08-18 14:10:47.426 [INF] NTFN: New confirmation subscription: conf_id=3, txid=fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a, num_confs=3 height_hint=644278
2020-08-18 14:10:47.426 [INF] FNDG: Waiting for funding tx (fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a) to reach 3 confirmations
2020-08-20 16:27:20.181 [WRN] FNDG: ChainNotifier shutting down, cannot complete funding flow for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1)
2020-08-20 16:27:20.198 [ERR] FNDG: Unable to advance pending state of ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1): error waiting for funding confirmation for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1): waiting for fundingconfirmation failed
2020-08-20 17:05:23.357 [INF] NTFN: New spend subscription: spend_id=26, outpoint=fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1, script=0 6e52b92e00d423495dcfd2702f1598c637363a0ced0450deef37b83a941937d9, height_hint=644578
2020-08-20 17:05:23.358 [INF] NTFN: Dispatching historical spend rescan for outpoint=fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1, script=0 6e52b92e00d423495dcfd2702f1598c637363a0ced0450deef37b83a941937d9, start=644578, end=644581
2020-08-20 17:05:26.763 [INF] CNCT: Close observer for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1) active
2020-08-20 17:05:29.737 [INF] CNCT: ChannelArbitrator(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1): starting state=StateDefault, trigger=chainTrigger, triggerHeight=644581
2020-08-20 17:08:52.045 [INF] NTFN: New confirmation subscription: conf_id=3, txid=fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a, num_confs=3 height_hint=644578
2020-08-20 17:08:52.045 [INF] FNDG: Waiting for funding tx (fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a) to reach 3 confirmations
2020-08-20 17:08:53.642 [WRN] CHBU: Replacing disk backup for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1) w/ newer version
2020-08-20 17:08:59.313 [INF] PEER: NodeKey(03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) loading ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1)
2020-08-20 17:08:59.314 [WRN] PEER: Unable to find our forwarding policy for channel fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1, using default values
2020-08-21 06:03:00.297 [WRN] CHBU: Replacing disk backup for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1) w/ newer version
2020-08-21 07:59:18.030 [WRN] CHBU: Replacing disk backup for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1) w/ newer version
2020-08-23 07:08:14.527 [INF] LNWL: Marking unconfirmed transaction fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a mined in block 644954
2020-08-23 07:12:34.320 [INF] NTFN: Dispatching 3 confirmation notification for txid=fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a
2020-08-23 07:12:34.332 [INF] FNDG: ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1) is now active: ChannelID(1ac1bd8a3e2b2828e0c4603d8db99ce177ed811410913b1e2c4fa10797132bfa)
2020-08-23 07:12:36.404 [WRN] CHBU: Replacing disk backup for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1) w/ newer version
2020-08-23 07:12:36.674 [WRN] CHBU: Replacing disk backup for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1) w/ newer version
2020-08-23 07:12:37.647 [INF] NTFN: New confirmation subscription: conf_id=7, txid=fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a, num_confs=6 height_hint=644954
2020-08-23 07:34:03.073 [INF] NANN: Announcing channel(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1) disabled [detected]
2020-08-23 07:41:01.649 [INF] NTFN: Dispatching 6 confirmation notification for txid=fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a
2020-08-23 07:41:01.651 [INF] FNDG: Announcing ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1), short_chan_id=644954:695:1
2020-08-23 14:10:59.416 [INF] PEER: NodeKey(03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) loading ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1)
2020-08-23 14:10:59.418 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1)
2020-08-23 16:37:11.737 [WRN] CHBU: Replacing disk backup for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1) w/ newer version
2020-08-23 19:18:20.788 [INF] NTFN: New spend subscription: spend_id=51, outpoint=fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1, script=0 6e52b92e00d423495dcfd2702f1598c637363a0ced0450deef37b83a941937d9, height_hint=645016
2020-08-23 19:18:20.789 [INF] NTFN: Dispatching historical spend rescan for outpoint=fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1, script=0 6e52b92e00d423495dcfd2702f1598c637363a0ced0450deef37b83a941937d9, start=645016, end=645036
2020-08-23 19:18:26.576 [INF] CNCT: Close observer for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1) active
2020-08-23 19:18:27.347 [INF] CNCT: ChannelArbitrator(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1): starting state=StateDefault, trigger=chainTrigger, triggerHeight=645036
2020-08-23 19:21:47.777 [WRN] CHBU: Replacing disk backup for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1) w/ newer version
2020-08-23 19:21:57.479 [WRN] CHBU: Replacing disk backup for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1) w/ newer version
2020-08-23 19:23:51.796 [INF] PEER: NodeKey(03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) loading ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1)
2020-08-23 19:23:51.799 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1)
2020-08-23 21:36:16.908 [WRN] CHBU: Replacing disk backup for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1) w/ newer version
2020-08-23 23:57:08.842 [WRN] CHBU: Replacing disk backup for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1) w/ newer version
2020-08-24 01:14:00.737 [INF] PEER: NodeKey(03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) loading ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1)
2020-08-24 01:14:00.739 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1)
2020-08-24 01:23:36.197 [INF] PEER: NodeKey(03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) loading ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1)
2020-08-24 01:23:36.199 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1)
2020-08-24 05:16:56.710 [INF] NTFN: New spend subscription: spend_id=29, outpoint=fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1, script=0 6e52b92e00d423495dcfd2702f1598c637363a0ced0450deef37b83a941937d9, height_hint=645098
2020-08-24 05:16:56.710 [INF] NTFN: Dispatching historical spend rescan for outpoint=fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1, script=0 6e52b92e00d423495dcfd2702f1598c637363a0ced0450deef37b83a941937d9, start=645098, end=645100
2020-08-24 05:16:59.396 [INF] CNCT: Close observer for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1) active
2020-08-24 05:17:02.903 [INF] CNCT: ChannelArbitrator(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1): starting state=StateDefault, trigger=chainTrigger, triggerHeight=645100
2020-08-24 05:17:06.840 [WRN] CHBU: Replacing disk backup for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1) w/ newer version
2020-08-24 05:17:14.264 [INF] PEER: NodeKey(03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) loading ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1)
2020-08-24 05:17:14.265 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1)
2020-08-24 10:04:26.067 [INF] PEER: NodeKey(03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) loading ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1)
2020-08-24 10:04:26.068 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1)

2020-08-28 03:10:06.757 [INF] NTFN: New spend subscription: spend_id=33, outpoint=fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1, script=0 6e52b92e00d423495dcfd2702f1598c637363a0ced0450deef37b83a941937d9, height_hint=645282
2020-08-28 03:10:06.757 [INF] NTFN: Dispatching historical spend rescan for outpoint=fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1, script=0 6e52b92e00d423495dcfd2702f1598c637363a0ced0450deef37b83a941937d9, start=645282, end=645632
2020-08-28 03:10:11.156 [INF] CNCT: Close observer for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1) active
2020-08-28 03:10:13.434 [INF] CNCT: ChannelArbitrator(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1): starting state=StateDefault, trigger=chainTrigger, triggerHeight=645632
2020-08-28 03:16:52.656 [WRN] CHBU: Replacing disk backup for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1) w/ newer version
2020-08-28 03:18:55.994 [INF] PEER: NodeKey(03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) loading ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1)
2020-08-28 03:18:56.002 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1)
2020-08-28 07:34:29.615 [INF] PEER: NodeKey(03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) loading ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1)
2020-08-28 07:34:29.681 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1)

You can see that the channel can not be seen at 1ml

Your environment

lnd version 0.11.0-beta commit=v0.11.0-beta
Linux rock64 4.4.132-1075-rockchip-ayufan-ga83beded8524 #1 SMP Thu Jul 26 08:22:22 UTC 2018 aarch64 GNU/Linux

@t-bast maybe you can also have a look from your side?

@Roasbeef
Copy link
Member

Roasbeef commented Sep 1, 2020

If you connect to the peer manually does the channel flip to active?

@Roasbeef Roasbeef added p2p Code related to the peer-to-peer behaviour server labels Sep 1, 2020
@t-bast
Copy link
Contributor

t-bast commented Sep 1, 2020

From our point of view, we've sent a FundingSigned at time 2020-08-18 14:10:46,966 UTC and then we haven't received anything.

Can you check on the lnd side whether this message was correctly received, and why no FundingSigned was sent from your node to ours?

@manreo
Copy link
Contributor Author

manreo commented Sep 1, 2020

@Roasbeef

admin@rock64:~/download/RTL$ lncli connect 03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f@34.239.230.56:9735
[lncli] rpc error: code = Unknown desc = already connected to peer: 03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f@34.239.230.56:9735
admin@rock64:~/download/RTL$ lncli connect 03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f@of7husrflx7sforh3fw6yqlpwstee3wg5imvvmkp4bz6rbjxtg5nljad.onion:9735
[lncli] rpc error: code = Unknown desc = already connected to peer: 03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f@34.239.230.56:9735

@t-bast thanks for time point:
https://pastebin.pl/view/1ffac9c7

@Roasbeef if you look closely you can see that I got 2 fundingResponse in close proximity. The first channel is stable and active, the second (With @t-bast ) is not.

Thanks

@t-bast
Copy link
Contributor

t-bast commented Sep 1, 2020

I don't know how to interpret the lnd logs but roasbeef or someone else from the lnd team should be able to help.

I think that what roasbeef meant was to first disconnect from the ACINQ node and then reconnect, and see if that unblocked the issue (by triggering a re-send of the lost funding messages).

@manreo
Copy link
Contributor Author

manreo commented Sep 1, 2020

Thanks @t-bast I already restarted the node a couple of times, but anyway I tried what you suggest, and
I can see something interesting in the log:

2020-09-01 13:54:21.860 [INF] SRVR: Disconnecting from 03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f@34.239.230.56:9735
2020-09-01 13:54:21.860 [INF] PEER: disconnecting 03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f@34.239.230.56:9735, reason: server: disconnecting peer 03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f@34.239.230.56:9735
2020-09-01 13:54:21.860 [INF] PEER: unable to read message from 03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f@34.239.230.56:9735: read tcp 127.0.0.1:37968->127.0.0.1:9050: use of closed network connection
2020-09-01 13:54:22.061 [INF] DISC: Removing GossipSyncer for peer=03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f
2020-09-01 13:54:32.736 [INF] DISC: GossipSyncer(024b8019795ec753fcdb1eb21ecd319bfab6a8b05e017f357dc5f052a181fb8c91): applying new update horizon: start=2042-07-14 01:04:00 +0000 UTC, end=2042-07-14 01:04:00 +0000 UTC, backlog_size=0
2020-09-01 13:54:37.279 [INF] DISC: Broadcasting 89 new announcements in 9 sub batches
2020-09-01 13:54:38.593 [INF] SRVR: Established connection to: 03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f@of7husrflx7sforh3fw6yqlpwstee3wg5imvvmkp4bz6rbjxtg5nljad.onion:9735
2020-09-01 13:54:38.593 [INF] SRVR: Finalizing connection to 03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f@of7husrflx7sforh3fw6yqlpwstee3wg5imvvmkp4bz6rbjxtg5nljad.onion:9735, inbound=false
2020-09-01 13:54:39.355 [INF] PEER: NodeKey(03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) loading ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1)
2020-09-01 13:54:39.376 [INF] HSWC: Removing channel link with ChannelID(1ac1bd8a3e2b2828e0c4603d8db99ce177ed811410913b1e2c4fa10797132bfa)
2020-09-01 13:54:39.376 [INF] HSWC: ChannelLink(644954:695:1): starting
2020-09-01 13:54:39.376 [INF] HSWC: Trimming open circuits for chan_id=644954:695:1, start_htlc_id=0
2020-09-01 13:54:39.376 [INF] HSWC: Adding live link chan_id=1ac1bd8a3e2b2828e0c4603d8db99ce177ed811410913b1e2c4fa10797132bfa, short_chan_id=644954:695:1
2020-09-01 13:54:39.377 [INF] HSWC: ChannelLink(644954:695:1): HTLC manager started, bandwidth=4427595000 mSAT
2020-09-01 13:54:39.377 [INF] HSWC: ChannelLink(644954:695:1): attempting to re-resynchronize
2020-09-01 13:54:39.376 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1)
2020-09-01 13:54:39.377 [INF] PEER: Negotiated chan series queries with 03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f
2020-09-01 13:54:39.378 [INF] DISC: Creating new GossipSyncer for peer=03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f
2020-09-01 13:54:40.153 [WRN] HSWC: ChannelLink(644954:695:1): error when syncing channel states: first message sent to sync should be ChannelReestablish, instead received: *lnwire.Error
2020-09-01 13:54:40.154 [ERR] HSWC: ChannelLink(644954:695:1): failing link: unable to synchronize channel states: first message sent to sync should be ChannelReestablish, instead received: *lnwire.Error with error: unable to resume channel, recovery required
2020-09-01 13:54:40.157 [INF] HSWC: ChannelLink(644954:695:1): exited
2020-09-01 13:54:40.157 [INF] HSWC: Removing channel link with ChannelID(1ac1bd8a3e2b2828e0c4603d8db99ce177ed811410913b1e2c4fa10797132bfa)
2020-09-01 13:54:40.163 [INF] HSWC: ChannelLink(644954:695:1): stopping
2020-09-01 13:54:59.833 [INF] CRTR: Processed channels=0 updates=17 nodes=5 in last 59.999955737s
2020-09-01 13:55:54.704 [INF] DISC: GossipSyncer(02607c9c92b7fa405dd27d8114d5ba1e6c04bf8757bef18b3649bffa2691d7638c): applying new update horizon: start=2042-07-14 01:04:00 +0000 UTC, end=2042-07-14 01:04:00 +0000 UTC, backlog_size=0

Thanks

@t-bast
Copy link
Contributor

t-bast commented Sep 1, 2020

Interesting, I don't know what these errors internally mean to lnd...let's see what the experts say ;)

@Roasbeef
Copy link
Member

Roasbeef commented Sep 4, 2020

From what I've seen the channel funding flow succeeded as normal. However, possibly the eclair node is rejecting the channel now?

2020-09-01 13:54:40.153 [WRN] HSWC: ChannelLink(644954:695:1): error when syncing channel states: first message sent to sync should be ChannelReestablish, instead received: *lnwire.Error

Only thing I can think of is if the channel too a while to confirm initially based on the user setting a very low fee:

Manual fee rate input of 250 sat/kw is too low, using 253 sat/kw instead

From there possibly eclair forgot the channel if it took too long to confirm. lnd will forget such channels after about 2 days or so, not sure how long eclair will hold on to them. From the logs I see the connection established, then the channel flip to active, but if the connection isn't stable for some reason, then it won't remain active.

To summarize I don't see anything out of the ordinary here other than possibly a lack of stability between the p2p node connection.

@manreo
Copy link
Contributor Author

manreo commented Sep 4, 2020

@Roasbeef I don't get your reply..? It reads to me as you are saying "That's your problem, you should have used a higher fee". I must say I don't care about if need for force-closing the channel (If this is that solution), but I feel that this can come back and bite us in the ass once people will start using the lightning network. Even if this error will happen on 0.1% of the channels or even on 0.01%, it will be a lot of dead channels.

From there possibly eclair forgot the channel if it took too long to confirm. lnd will forget such channels after about 2 days or so

To your points, I did use 1 sat for byte, I always use it, sometimes it can take weeks until my channels are "confirmed" I never had this problem. Shouldn't this be something in the lightning-rfc ?

Look again on what @t-bast stated:

From our point of view, we've sent a FundingSigned at time 2020-08-18 14:10:46,966 UTC and then we haven't received anything.

Can you check on the lnd side whether this message was correctly received, and why no FundingSigned was sent from your node to ours?

It does not look as eclair forgot the channel, it is more that lnd did not send the FundingSigned...

To summarize - what do you think I should do now? Is there any improvement to lnd/ecliar/lightning that will make it so that this thing will not happen again?
Thank you

@t-bast
Copy link
Contributor

t-bast commented Sep 7, 2020

Sorry I mistyped here, it's normal that lnd sends no FundingSigned, only the fundee is sending that message, I meant FundingLocked but I found it 5 days later when the transaction confirmed.

I've been digging through our logs over a longer period of time, and it seems like the issue is somehow linked to ChannelReestablish:

2020-08-18 14:10:29,781 INFO  f.a.e.i.ReconnectionTask CON n:032de549c153a4e125f37c3faf1bf2c02c70b40df23c7a51635078acb12d999557 - peer is connected
2020-08-18 14:10:46,425 INFO  f.a.e.i.Peer n:032de549c153a4e125f37c3faf1bf2c02c70b40df23c7a51635078acb12d999557 c:35f3ea5996ea9db81d6f417bbe18d4ad660903077fa9d01a53c12f1cfa8d6e4b - IN msg=OpenChannel(6fe28c0ab6f1b372c1a6a246ae63f74f931e8365e15a089c68d6190000000000,35f3ea5996ea9db81d6f417bbe18d4ad660903077fa9d01a53c12f1cfa8d6e4b,Satoshi(4500000),0 msat,Satoshi(573),4455000000,Satoshi(45000),1 msat,30586,CltvExpiryDelta(540),483,037142dd50561cc5e65dc55be821bf401a0ddd0226431d79fea3d9c87e6310c328,03b6dc05e7d2e2b2706c7c4d990c3ac2d3947acd79fba4a6ab05936d7b671a4c47,02d61dad155cfec684af5fcb8ceccfab0cee6a722b616ff6905aea29d10c94f485,02e942121fb6cca14ce6b96428b98fc7691d39cb69698ebbaa2782f308648d62ff,03907889a4d7ac23b0b6063b211b1faa4cbd8d151053d674349815f2b5ec3d787a,034b9012f4072874d92ec580e6d86501be62c9b0dd1849b17347359780bc4bc5e7,1,TlvStream(List(UpfrontShutdownScript(ByteVector(empty))),List()))
2020-08-18 14:10:46,437 INFO  fr.acinq.eclair.io.Peer n:032de549c153a4e125f37c3faf1bf2c02c70b40df23c7a51635078acb12d999557 c:35f3ea5996ea9db81d6f417bbe18d4ad660903077fa9d01a53c12f1cfa8d6e4b - accepting a new channel with temporaryChannelId=35f3ea5996ea9db81d6f417bbe18d4ad660903077fa9d01a53c12f1cfa8d6e4b localParams=LocalParams(03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f,m/428689552/2075998881/1324577630'/257306340/304467210'/1949018092/2083251782'/732443205/0',Satoshi(546),20000000000,Satoshi(45000),1 msat,CltvExpiryDelta(720),30,false,ByteVector(22 bytes, 0x0014ce1f4b73993641e3a87ccc95b85ad06e5b209dde),None,Features(HashSet(ActivatedFeature(payment_secret,optional), ActivatedFeature(option_data_loss_protect,optional), ActivatedFeature(gossip_queries_ex,optional), ActivatedFeature(option_support_large_channel,optional), ActivatedFeature(gossip_queries,optional), ActivatedFeature(initial_routing_sync,optional), ActivatedFeature(var_onion_optin,optional), ActivatedFeature(basic_mpp,optional)),Set()))
2020-08-18 14:10:46,438 INFO  f.a.e.channel.Channel n:032de549c153a4e125f37c3faf1bf2c02c70b40df23c7a51635078acb12d999557 c:35f3ea5996ea9db81d6f417bbe18d4ad660903077fa9d01a53c12f1cfa8d6e4b - received OpenChannel=OpenChannel(6fe28c0ab6f1b372c1a6a246ae63f74f931e8365e15a089c68d6190000000000,35f3ea5996ea9db81d6f417bbe18d4ad660903077fa9d01a53c12f1cfa8d6e4b,Satoshi(4500000),0 msat,Satoshi(573),4455000000,Satoshi(45000),1 msat,30586,CltvExpiryDelta(540),483,037142dd50561cc5e65dc55be821bf401a0ddd0226431d79fea3d9c87e6310c328,03b6dc05e7d2e2b2706c7c4d990c3ac2d3947acd79fba4a6ab05936d7b671a4c47,02d61dad155cfec684af5fcb8ceccfab0cee6a722b616ff6905aea29d10c94f485,02e942121fb6cca14ce6b96428b98fc7691d39cb69698ebbaa2782f308648d62ff,03907889a4d7ac23b0b6063b211b1faa4cbd8d151053d674349815f2b5ec3d787a,034b9012f4072874d92ec580e6d86501be62c9b0dd1849b17347359780bc4bc5e7,1,TlvStream(List(UpfrontShutdownScript(ByteVector(empty))),List()))
2020-08-18 14:10:46,442 INFO  f.a.e.i.Peer n:032de549c153a4e125f37c3faf1bf2c02c70b40df23c7a51635078acb12d999557 c:35f3ea5996ea9db81d6f417bbe18d4ad660903077fa9d01a53c12f1cfa8d6e4b - OUT msg=AcceptChannel(35f3ea5996ea9db81d6f417bbe18d4ad660903077fa9d01a53c12f1cfa8d6e4b,Satoshi(546),20000000000,Satoshi(45000),1 msat,3,CltvExpiryDelta(720),30,026d31decc8509ff980f23f76b0a0111cbc0f79c6ae50b004f91545747d4ca3ab8,028d30232716f8d39c86779b471f52712d670f0f0841a5abe557fdabafb9548a70,03a83213df77944753bebaf7b83cec7cecd508496af34c383fbd25231cd66ae8e8,02fd62913dd6ac9886febdf3520152b4970952bc18b08532efd47d84333cc93e53,029a268ce951bfd7505b430421f3c30c8f57062906b7d3c7509af34aa780870851,02788baa99502f2e7b366603fa45c07569329d23ea0737b6519f3794e30cc827d4,TlvStream(ArraySeq(UpfrontShutdownScript(ByteVector(empty))),List()))
2020-08-18 14:10:46,957 INFO  f.a.e.i.Peer n:032de549c153a4e125f37c3faf1bf2c02c70b40df23c7a51635078acb12d999557 c:35f3ea5996ea9db81d6f417bbe18d4ad660903077fa9d01a53c12f1cfa8d6e4b - IN msg=FundingCreated(35f3ea5996ea9db81d6f417bbe18d4ad660903077fa9d01a53c12f1cfa8d6e4b,1ac1bd8a3e2b2828e0c4603d8db99ce177ed811410913b1e2c4fa10797132bfb,1,f67efe85b4c1e62dde6a69ba2d1cc019b21026b759038143d0dec0e026b3cc5b5c19463db3d19b9b280fd94d9dc8acfc542ef8880d23a2d6b497d1698650c406)
2020-08-18 14:10:46,959 INFO  f.a.e.channel.Channel n:032de549c153a4e125f37c3faf1bf2c02c70b40df23c7a51635078acb12d999557 c:35f3ea5996ea9db81d6f417bbe18d4ad660903077fa9d01a53c12f1cfa8d6e4b - waiting for them to publish the funding tx for channelId=1ac1bd8a3e2b2828e0c4603d8db99ce177ed811410913b1e2c4fa10797132bfa fundingTxid=fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a
2020-08-18 14:10:46,959 INFO  fr.acinq.eclair.io.Peer n:032de549c153a4e125f37c3faf1bf2c02c70b40df23c7a51635078acb12d999557 - channel id switch: previousId=35f3ea5996ea9db81d6f417bbe18d4ad660903077fa9d01a53c12f1cfa8d6e4b nextId=1ac1bd8a3e2b2828e0c4603d8db99ce177ed811410913b1e2c4fa10797132bfa
2020-08-18 14:10:46,966 INFO  f.a.e.i.Peer n:032de549c153a4e125f37c3faf1bf2c02c70b40df23c7a51635078acb12d999557 c:1ac1bd8a3e2b2828e0c4603d8db99ce177ed811410913b1e2c4fa10797132bfa - OUT msg=FundingSigned(1ac1bd8a3e2b2828e0c4603d8db99ce177ed811410913b1e2c4fa10797132bfa,ac3a37adcb66e5c76337e09172c73782495290986091f6b001ddffc3bc3daf2c666f033063bc5583a9fb349754f622678436da16f67f201f16cd0e64b2211a05,None)

...then no activity happens as the funding tx is waiting for confirmation...

...but a disconnection happens where your node seems unreachable for ~40 minutes...
2020-08-20 16:27:20,635 INFO  fr.acinq.eclair.io.Peer CON n:032de549c153a4e125f37c3faf1bf2c02c70b40df23c7a51635078acb12d999557 - connection lost
2020-08-20 16:27:20,635 INFO  f.a.e.i.ReconnectionTask CON n:032de549c153a4e125f37c3faf1bf2c02c70b40df23c7a51635078acb12d999557 - peer is disconnected
2020-08-20 17:08:59,223 INFO  f.a.e.i.ReconnectionTask CON n:032de549c153a4e125f37c3faf1bf2c02c70b40df23c7a51635078acb12d999557 - peer is connected
2020-08-20 17:08:59,225 INFO  f.a.e.i.Peer CON n:032de549c153a4e125f37c3faf1bf2c02c70b40df23c7a51635078acb12d999557 c:1ac1bd8a3e2b2828e0c4603d8db99ce177ed811410913b1e2c4fa10797132bfa - OUT msg=ChannelReestablish(1ac1bd8a3e2b2828e0c4603d8db99ce177ed811410913b1e2c4fa10797132bfa,1,0,PrivateKey(0000000000000000000000000000000000000000000000000000000000000000),02788baa99502f2e7b366603fa45c07569329d23ea0737b6519f3794e30cc827d4,None)

...then no activity for 3 days...

...then the funding tx confirms...
2020-08-23 07:12:36,149 INFO  f.a.e.i.Peer n:032de549c153a4e125f37c3faf1bf2c02c70b40df23c7a51635078acb12d999557 c:1ac1bd8a3e2b2828e0c4603d8db99ce177ed811410913b1e2c4fa10797132bfa - IN msg=FundingLocked(1ac1bd8a3e2b2828e0c4603d8db99ce177ed811410913b1e2c4fa10797132bfa,03719b07b0d77ca578adf8799a361a00c31b1807a7e54e001d02e023431f28e87b)
2020-08-23 07:12:36,149 WARN  f.a.e.channel.Channel n:032de549c153a4e125f37c3faf1bf2c02c70b40df23c7a51635078acb12d999557 c:1ac1bd8a3e2b2828e0c4603d8db99ce177ed811410913b1e2c4fa10797132bfa - unhandled event FundingLocked(1ac1bd8a3e2b2828e0c4603d8db99ce177ed811410913b1e2c4fa10797132bfa,03719b07b0d77ca578adf8799a361a00c31b1807a7e54e001d02e023431f28e87b) in state SYNCING

It looks like we never receive a ChannelReestablish (but we have sent one at time 2020-08-20 17:08:59,225).
This causes us to drop the FundingLocked message and then end up considering that the channel never completed the funding flow.

Can you check your logs around times 2020-08-20 17:08:59,225 (where we send a ChannelReestablish) and 2020-08-23 07:12:36,149 (where you send a FundingLocked)?
We need to understand if there is an issue where lnd isn't sending a ChannelReestablish where it should, or whether it's correctly sent but it's lost on our side (or lost in-flight).

I suspect that this could be an issue with reconnection handling somewhere...
Or could it be related to what @Roasbeef said about lnd forgetting the channel after 2 days? Could it be the reason why lnd doesn't send a channel_reestablish (it seems a bit surprising since lnd does send the funding_locked, but maybe that's an area to investigate).

@manreo
Copy link
Contributor Author

manreo commented Sep 7, 2020

Thanks @t-bast
These are the logs at these time, see last two lines about sending "FundingLocked":

2020-08-23 07:08:00.130 [INF] CRTR: Processed channels=5 updates=56 nodes=2 in last 59.999861175s
2020-08-23 07:08:14.413 [INF] CRTR: Pruning channel graph using block 0000000000000000000a92fbf719ff61af9bf0f87d8c64facfbd3afc05c71364 (height=644954)
2020-08-23 07:08:14.527 [INF] LNWL: Marking unconfirmed transaction fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a mined in block 644954
2020-08-23 07:08:15.056 [INF] CRTR: Block 0000000000000000000a92fbf719ff61af9bf0f87d8c64facfbd3afc05c71364 (height=644954) closed 1 channels
2020-08-23 07:08:15.165 [INF] LNWL: Marking unconfirmed transaction 09164b0b2514b6f1fd3aa9e6b856c3281337ee3f12a5066cb3ef1254e51b51e2 mined in block 644954
2020-08-23 07:08:16.078 [INF] NTFN: New block: height=644954, sha=0000000000000000000a92fbf719ff61af9bf0f87d8c64facfbd3afc05c71364
2020-08-23 07:08:16.080 [INF] UTXN: Attempting to graduate height=644954: num_kids=0, num_babies=0
2020-08-23 07:08:16.125 [INF] HSWC: Garbage collected 1 shared secret hashes at height=644954
2020-08-23 07:08:30.111 [INF] DISC: Broadcasting 64 new announcements in 7 sub batches
2020-08-23 07:08:50.914 [INF] CRTR: Examining channel graph for zombie channels
2020-08-23 07:08:50.985 [INF] CRTR: Pruning 0 zombie channels
2020-08-23 07:09:00.131 [INF] CRTR: Processed channels=0 updates=42 nodes=5 in last 59.999926327s
2020-08-23 07:09:42.179 [INF] HSWC: ChannelLink(633094:2293:0): updating commit fee to 25982 sat/kw sat/kw
2020-08-23 07:09:42.179 [ERR] HSWC: ChannelLink(633094:2293:0): unable to update fee rate: cannot apply fee_update=25982 sat/kw, new balance=0.0000591 BTC would dip below channel reserve=0.000095 BTC
2020-08-23 07:10:00.111 [INF] DISC: Broadcasting 48 new announcements in 5 sub batches
2020-08-23 07:10:00.130 [INF] CRTR: Processed channels=0 updates=2 nodes=0 in last 59.99935662s
2020-08-23 07:10:04.699 [INF] CRTR: Pruning channel graph using block 0000000000000000000953b7b531e5c54ff55f9845389003db2b8c375508184d (height=644955)
2020-08-23 07:10:04.950 [INF] CRTR: Block 0000000000000000000953b7b531e5c54ff55f9845389003db2b8c375508184d (height=644955) closed 0 channels
2020-08-23 07:10:06.175 [INF] NTFN: New block: height=644955, sha=0000000000000000000953b7b531e5c54ff55f9845389003db2b8c375508184d
2020-08-23 07:10:06.177 [INF] UTXN: Attempting to graduate height=644955: num_kids=0, num_babies=0
2020-08-23 07:11:00.131 [INF] CRTR: Processed channels=0 updates=34 nodes=2 in last 59.999829309s
2020-08-23 07:11:30.111 [INF] DISC: Broadcasting 38 new announcements in 4 sub batches
2020-08-23 07:12:00.131 [INF] CRTR: Processed channels=7 updates=37 nodes=5 in last 59.999583765s
2020-08-23 07:12:33.244 [INF] CRTR: Pruning channel graph using block 00000000000000000008971a9c0b4e7991565ca1d2692de7c9bd99f105de8d7d (height=644956)
2020-08-23 07:12:33.454 [INF] CRTR: Block 00000000000000000008971a9c0b4e7991565ca1d2692de7c9bd99f105de8d7d (height=644956) closed 0 channels
2020-08-23 07:12:34.320 [INF] NTFN: New block: height=644956, sha=00000000000000000008971a9c0b4e7991565ca1d2692de7c9bd99f105de8d7d
2020-08-23 07:12:34.323 [INF] UTXN: Attempting to graduate height=644956: num_kids=0, num_babies=0
2020-08-23 07:12:34.320 [INF] NTFN: Dispatching 3 confirmation notification for txid=fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a
2020-08-23 07:12:34.325 [INF] NTFN: Dispatching 3 confirmation notification for txid=09164b0b2514b6f1fd3aa9e6b856c3281337ee3f12a5066cb3ef1254e51b51e2
2020-08-23 07:12:34.332 [INF] FNDG: ChannelPoint(fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a:1) is now active: ChannelID(1ac1bd8a3e2b2828e0c4603d8db99ce177ed811410913b1e2c4fa10797132bfa)
2020-08-23 07:12:34.332 [INF] FNDG: ChannelPoint(09164b0b2514b6f1fd3aa9e6b856c3281337ee3f12a5066cb3ef1254e51b51e2:1) is now active: ChannelID(e2511be55412efb36c06a5123fee371328c356b8e6a93afdf1b614250b4b1608)
2020-08-23 07:12:35.921 [ERR] FNDG: unable to report short chan id: link 1ac1bd8a3e2b2828e0c4603d8db99ce177ed811410913b1e2c4fa10797132bfa not found
2020-08-23 07:12:35.921 [ERR] FNDG: unable to report short chan id: link e2511be55412efb36c06a5123fee371328c356b8e6a93afdf1b614250b4b1608 not found
2020-08-23 07:12:35.942 [INF] FNDG: Peer(03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f) is online, sending FundingLocked for ChannelID(1ac1bd8a3e2b2828e0c4603d8db99ce177ed811410913b1e2c4fa10797132bfa)
2020-08-23 07:12:35.945 [INF] FNDG: Peer(037f990e61acee8a7697966afd29dd88f3b1f8a7b14d625c4f8742bd952003a590) is online, sending FundingLocked for ChannelID(e2511be55412efb36c06a5123fee371328c356b8e6a93afdf1b614250b4b1608)

Interestingly at the same time there is an update to the channelpoint:
https://pastebin.pl/view/aa59e22d

and then there is a new confirmation subscription, don't know what it means.

2020-08-23 07:12:37.647 [INF] NTFN: New confirmation subscription: conf_id=7, txid=fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a, num_confs=6 height_hint=644954
2020-08-23 07:12:37.765 [INF] NTFN: New confirmation subscription: conf_id=8, txid=09164b0b2514b6f1fd3aa9e6b856c3281337ee3f12a5066cb3ef1254e51b51e2, num_confs=6 height_hint=644954
2020-08-23 07:12:45.137 [INF] PEER: New channel active ChannelPoint(09164b0b2514b6f1fd3aa9e6b856c3281337ee3f12a5066cb3ef1254e51b51e2:1) with NodeKey(037f990e61acee8a7697966afd29dd88f3b1f8a7b14d625c4f8742bd952003a590)
2020-08-23 07:12:45.138 [INF] HSWC: Removing channel link with ChannelID(e2511be55412efb36c06a5123fee371328c356b8e6a93afdf1b614250b4b1608)
2020-08-23 07:12:45.138 [INF] HSWC: ChannelLink(644954:703:1): starting
2020-08-23 07:12:45.138 [INF] HSWC: Trimming open circuits for chan_id=644954:703:1, start_htlc_id=0
2020-08-23 07:12:45.139 [INF] HSWC: Adding live link chan_id=e2511be55412efb36c06a5123fee371328c356b8e6a93afdf1b614250b4b1608, short_chan_id=644954:703:1
2020-08-23 07:12:45.139 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(09164b0b2514b6f1fd3aa9e6b856c3281337ee3f12a5066cb3ef1254e51b51e2:1)
2020-08-23 07:12:45.139 [INF] HSWC: ChannelLink(644954:703:1): HTLC manager started, bandwidth=1457595000 mSAT
2020-08-23 07:12:45.139 [INF] HSWC: ChannelLink(644954:703:1): attempting to re-resynchronize
2020-08-23 07:12:45.479 [INF] HSWC: ChannelLink(644954:703:1): resending FundingLocked message to peer
2020-08-23 07:12:45.480 [INF] HSWC: ChannelLink(644954:703:1): received re-establishment message from remote side
2020-08-23 07:12:45.808 [INF] FNDG: Received duplicate fundingLocked for ChannelID(e2511be55412efb36c06a5123fee371328c356b8e6a93afdf1b614250b4b1608), ignoring.
2020-08-23 07:13:00.111 [INF] DISC: Broadcasting 54 new announcements in 6 sub batches
2020-08-23 07:13:00.131 [INF] CRTR: Processed channels=5 updates=6 nodes=1 in last 59.999882879s

it happens to two channels at the same time.
Also I see that e2511be55412efb36c06a5123fee371328c356b8e6a93afdf1b614250b4b1608 duplicate fundingLocked` don't know what it means.

I don't know how lnd mark "ChannelReestablish" in the logs @Roasbeef

Thanks

@Roasbeef
Copy link
Member

So turns out this is related to #4006 and might require some larger changes to properly fix. In the short term, we're looking to see if there's anything incremental we can do in this area.

@Roasbeef
Copy link
Member

Also in the future, please stick to using paste bins for logs so they don't consume so much space in issues.

@manreo
Copy link
Contributor Author

manreo commented Sep 27, 2020

@Roasbeef should I close the channel and try to reopen? or is it useful for you that I leave it in this Limbo state to see if the fix you'll provide is helpful?

@begetan
Copy link

begetan commented Sep 28, 2020

@mrmanpew you transaction was confirmed at block 644954 2020-08-23 09:07 after 5 days of submitting according your log https://mempool.space/tx/fb2b139707a14f2c1e3b91101481ed77e19cb98d3d60c4e028282b3e8abdc11a

So node probably have dropped this TX and removed channels from their database. You should follow a recovery procedure in this case.

Anyway, here is a quite serious question. In order to make Lightning Network efficient one should try open channels with low on-chain fee. But since commissions in Bitcoin is fluctuating highly it is quite possible to for cheap transaction to stack in mempool up to 5-7 days untill a next weekend.

@Roasbeef @t-bast
I would propose to set TX conformation limit to 7 days for all kind of nodes. You may see in the mempool graph some weekly periods with the high transaction fees.

image

@Crypt-iQ Crypt-iQ self-assigned this Sep 29, 2020
@Crypt-iQ
Copy link
Collaborator

You should probably not do anything until we completely diagnose the issue.

@Roasbeef
Copy link
Member

Roasbeef commented Oct 1, 2020

I would propose to set TX conformation limit to 7 days for all kind of nodes. You may see in the mempool graph some weekly periods with the high transaction fees.

Agree we should increase this value. The 2 days value was set 2-ish years ago, and these days you can really only have that kind of assumption on the weekends.

@manreo
Copy link
Contributor Author

manreo commented Nov 3, 2020

You should probably not do anything until we completely diagnose the issue.

@Roasbeef @guggero what am I going to do with this 4M transaction now that my node crushed #4720, I am in the process of SCB recovery, but I still get those:

2020-11-02 21:05:49.257 [ERR] HSWC: ChannelLink(560643:2801:1): failing link: unable to synchronize channel states: ChannelPoint(febeffbe5096cb4341d13d5d58793d86ee9395430f9518c1cdfee873c3b47260:1) with CommitPoint(03e6b5df5d7c22b0fb0415b443f56e72b23db7d52f7643258e03284fa11e7c3445) had possible local commitment state data loss with error: unable to resume channel, recovery required

from ACQIN

@manreo
Copy link
Contributor Author

manreo commented Nov 28, 2020

@Roasbeef @Crypt-iQ anything?

@guggero
Copy link
Collaborator

guggero commented Nov 30, 2020

@mrmanpew it looks like Acinq indeed removed the channel from their database. Otherwise it should respond to the DLP on your request and force close it.
Do you see any response from the Acinq peer in the log? Something like "channel not found" when your node tries to initiate DLP?
Do you still have the channel DB from before you started the recovery process?
I think this needs to be resolved manually, with either of the following two possibilities:

  • If you still have the channel DB, run step 8, 9 and 10 of this guide to manually force close from your end
  • If you don't have the channel DB from before, you need the help of Acinq to get the funds out of the multisig. I created the chantools rescuefunding command for that. But that requires Acinq to sign a PSBT which I hope they'd be willing to do?

@t-bast can you confirm the channel isn't in your database anymore?

@t-bast
Copy link
Contributor

t-bast commented Nov 30, 2020

We're not responding to DLP because lnd incorrectly sends funding_locked before sending channel_reestablish.
I'll check if we still have the channel in our DB.

@t-bast
Copy link
Contributor

t-bast commented Nov 30, 2020

We have indeed removed the channel from our DB (note that it has never been used, no HTLCs were exchanged, so you should be able to get your funds back easily).

@t-bast
Copy link
Contributor

t-bast commented Nov 30, 2020

Note that eclair responds with an unknown channel error to your DLP attempts, doesn't this appear in your logs?

@manreo
Copy link
Contributor Author

manreo commented Dec 1, 2020

thanks @guggero and @t-bast , I'm waiting for a new machine. (intel 4670). Once it will arrive I'll try the suggested solutions.
THanks

@manreo
Copy link
Contributor Author

manreo commented Dec 15, 2020

I managed to recover the channel with @guggero help, not sure what to do with this ticket as the problem still exists, and I can not help debug is anymore.

@t-bast
Copy link
Contributor

t-bast commented Dec 16, 2020

Good to know you've been able to recover the funds!

I think the root cause is still there, and is a small bug in lnd: lnd sometimes sends funding_locked before channel_reestablish, which is a spec violation and causes eclair to ignore messages. We've created a somewhat hacky mitigation in eclair (ACINQ/eclair#1563) but AFAIK lnd <-> c-lightning will also have this issue, so it's worth keeping an issue open until that is fixed.

@sangaman
Copy link
Contributor

I'm experiencing an issue that may be related to this one. I recently shut down my lnd node for the first time in at least a few weeks to update to the 0.12 rc, when I started back up I noticed that almost half my channels were inactive. This persists through restarts.

The logs show a bunch of connection/channel synchronization errors, here's a snippet:

2020-12-17 03:56:12.585 [INF] PEER: unable to read message from 02ad6fb8d693dc1e4569bcedefadf5f72a931ae027dc0f0c544b34c1c6f3b9a02b@167.99.50.31:9735: EOF
2020-12-17 03:56:12.586 [INF] PEER: disconnecting 02ad6fb8d693dc1e4569bcedefadf5f72a931ae027dc0f0c544b34c1c6f3b9a02b@167.99.50.31:9735, reason: read handler closed
2020-12-17 03:56:12.687 [INF] DISC: Removing GossipSyncer for peer=02ad6fb8d693dc1e4569bcedefadf5f72a931ae027dc0f0c544b34c1c6f3b9a02b
2020-12-17 03:56:12.687 [INF] HSWC: Removing channel link with ChannelID(2a17bca40b4a6a0a69d339a2b10c7f8c9e7da8333c512e0d374438106af0f058)
2020-12-17 03:56:12.687 [INF] HSWC: ChannelLink(551646:1653:0): stopping
2020-12-17 03:56:12.687 [WRN] HSWC: ChannelLink(551646:1653:0): error when syncing channel states: link shutting down
2020-12-17 03:56:12.688 [INF] HSWC: ChannelLink(551646:1653:0): exited
2020-12-17 03:56:18.579 [INF] SRVR: Established connection to: 02c91d6aa51aa940608b497b6beebcb1aec05be3c47704b682b3889424679ca490@213.174.156.65:9735
2020-12-17 03:56:18.579 [INF] SRVR: Finalizing connection to 02c91d6aa51aa940608b497b6beebcb1aec05be3c47704b682b3889424679ca490@213.174.156.65:9735, inbound=false
2020-12-17 03:56:18.584 [INF] PEER: Legacy channel open with peer: 02c91d6aa51aa940608b497b6beebcb1aec05be3c47704b682b3889424679ca490, downgrading static remote required feature bit to optional
2020-12-17 03:56:19.079 [INF] PEER: NodeKey(02c91d6aa51aa940608b497b6beebcb1aec05be3c47704b682b3889424679ca490) loading ChannelPoint(d2986f2e99ddfe66989f5463f7601683879f665ba4cf23352839542077d60b9b:0)
2020-12-17 03:56:19.081 [INF] HSWC: Removing channel link with ChannelID(9b0bd677205439283523cfa45b669f87831660f763549f9866fedd992e6f98d2)
2020-12-17 03:56:19.081 [INF] HSWC: ChannelLink(550341:759:0): starting
2020-12-17 03:56:19.082 [INF] HSWC: Trimming open circuits for chan_id=550341:759:0, start_htlc_id=23
2020-12-17 03:56:19.082 [INF] HSWC: Adding live link chan_id=9b0bd677205439283523cfa45b669f87831660f763549f9866fedd992e6f98d2, short_chan_id=550341:759:0
2020-12-17 03:56:19.082 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(d2986f2e99ddfe66989f5463f7601683879f665ba4cf23352839542077d60b9b:0)
2020-12-17 03:56:19.082 [INF] HSWC: ChannelLink(550341:759:0): HTLC manager started, bandwidth=7932721076 mSAT
2020-12-17 03:56:19.082 [INF] PEER: Negotiated chan series queries with 02c91d6aa51aa940608b497b6beebcb1aec05be3c47704b682b3889424679ca490
2020-12-17 03:56:19.083 [INF] HSWC: ChannelLink(550341:759:0): attempting to re-resynchronize
2020-12-17 03:56:19.083 [INF] DISC: Creating new GossipSyncer for peer=02c91d6aa51aa940608b497b6beebcb1aec05be3c47704b682b3889424679ca490
2020-12-17 03:56:19.085 [INF] PEER: disconnecting 02c91d6aa51aa940608b497b6beebcb1aec05be3c47704b682b3889424679ca490@213.174.156.65:9735, reason: unable to write message: write tcp 127.0.0.1:41820->127.0.0.1:9050: write: broken pipe
2020-12-17 03:56:19.085 [INF] PEER: unable to read message from 02c91d6aa51aa940608b497b6beebcb1aec05be3c47704b682b3889424679ca490@213.174.156.65:9735: EOF
2020-12-17 03:56:19.085 [WRN] HSWC: ChannelLink(550341:759:0): error when syncing channel states: unable to send chan sync message for ChannelPoint(d2986f2e99ddfe66989f5463f7601683879f665ba4cf23352839542077d60b9b:0): peer exiting
2020-12-17 03:56:19.086 [ERR] HSWC: ChannelLink(550341:759:0): failing link: unable to synchronize channel states: unable to send chan sync message for ChannelPoint(d2986f2e99ddfe66989f5463f7601683879f665ba4cf23352839542077d60b9b:0): peer exiting with error: unable to resume channel, recovery required

If I manually attempt to establish a connection to a peer with an inactive channel (using lncli connect) I get this log output.

2020-12-17 03:59:42.591 [INF] SRVR: Established connection to: 02c91d6aa51aa940608b497b6beebcb1aec05be3c47704b682b3889424679ca490@213.174.156.65:9735
2020-12-17 03:59:42.608 [INF] SRVR: Finalizing connection to 02c91d6aa51aa940608b497b6beebcb1aec05be3c47704b682b3889424679ca490@213.174.156.65:9735, inbound=false
2020-12-17 03:59:42.626 [INF] PEER: Legacy channel open with peer: 02c91d6aa51aa940608b497b6beebcb1aec05be3c47704b682b3889424679ca490, downgrading static remote required feature bit to optional
2020-12-17 03:59:43.548 [INF] PEER: NodeKey(02c91d6aa51aa940608b497b6beebcb1aec05be3c47704b682b3889424679ca490) loading ChannelPoint(d2986f2e99ddfe66989f5463f7601683879f665ba4cf23352839542077d60b9b:0)
2020-12-17 03:59:43.551 [INF] HSWC: Removing channel link with ChannelID(9b0bd677205439283523cfa45b669f87831660f763549f9866fedd992e6f98d2)
2020-12-17 03:59:43.554 [INF] HSWC: ChannelLink(550341:759:0): starting
2020-12-17 03:59:43.554 [INF] HSWC: Trimming open circuits for chan_id=550341:759:0, start_htlc_id=23
2020-12-17 03:59:43.554 [INF] HSWC: Adding live link chan_id=9b0bd677205439283523cfa45b669f87831660f763549f9866fedd992e6f98d2, short_chan_id=550341:759:0
2020-12-17 03:59:43.554 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(d2986f2e99ddfe66989f5463f7601683879f665ba4cf23352839542077d60b9b:0)
2020-12-17 03:59:43.555 [INF] PEER: Negotiated chan series queries with 02c91d6aa51aa940608b497b6beebcb1aec05be3c47704b682b3889424679ca490
2020-12-17 03:59:43.555 [INF] HSWC: ChannelLink(550341:759:0): HTLC manager started, bandwidth=7932721076 mSAT
2020-12-17 03:59:43.555 [INF] DISC: Creating new GossipSyncer for peer=02c91d6aa51aa940608b497b6beebcb1aec05be3c47704b682b3889424679ca490
2020-12-17 03:59:43.556 [INF] HSWC: ChannelLink(550341:759:0): attempting to re-resynchronize
2020-12-17 03:59:43.667 [INF] PEER: unable to read message from 02c91d6aa51aa940608b497b6beebcb1aec05be3c47704b682b3889424679ca490@213.174.156.65:9735: EOF
2020-12-17 03:59:43.668 [INF] PEER: disconnecting 02c91d6aa51aa940608b497b6beebcb1aec05be3c47704b682b3889424679ca490@213.174.156.65:9735, reason: read handler closed
2020-12-17 03:59:43.769 [INF] DISC: Removing GossipSyncer for peer=02c91d6aa51aa940608b497b6beebcb1aec05be3c47704b682b3889424679ca490
2020-12-17 03:59:43.769 [INF] HSWC: Removing channel link with ChannelID(9b0bd677205439283523cfa45b669f87831660f763549f9866fedd992e6f98d2)
2020-12-17 03:59:43.770 [INF] HSWC: ChannelLink(550341:759:0): stopping
2020-12-17 03:59:43.770 [WRN] HSWC: ChannelLink(550341:759:0): error when syncing channel states: link shutting down
2020-12-17 03:59:43.771 [INF] HSWC: ChannelLink(550341:759:0): exited

Is this a similar problem to what's described in this issue, or should I open a new issue? I'm hoping it's not anything related to data corruption, though I did enable db auto compaction right before encountering this so that could possibly be related. I can also share more logs on pastebin or reach out to someone on slack if that would be helpful in figuring out the issue. Thank you.

@t-bast
Copy link
Contributor

t-bast commented Dec 17, 2020

It's hard to tell @sangaman because your logs don't show your outgoing messages.
Maybe you need to turn on debug logs to check whether you're sending a funding_locked before a channel_reestablish?

The only thing I can conclude from your logs is that your remote closes the connection, but I need more logs to understand the reason why. Or if you experience this with the ACINQ node, I can check our logs to see if that's the same issue.

@carlaKC
Copy link
Collaborator

carlaKC commented Dec 17, 2020

I'm experiencing an issue that may be related to this one.

@sangaman this could be related to #4862. Of the peers that are inactive, is there any chance of you getting logs from them? If you know whether they're running lnd/eclair/clightning would also be helpful.

Could you also have a look at the ListChannels output and check the following fields for the inactive peers?

"static_remote_key": true,
"commitment_type": "STATIC_REMOTE_KEY",

@Crypt-iQ
Copy link
Collaborator

Possibly related if there are channel sync issues on startup: #4799

@sangaman
Copy link
Contributor

@sangaman this could be related to #4862. Of the peers that are inactive, is there any chance of you getting logs from them? If you know whether they're running lnd/eclair/clightning would also be helpful.

Could you also have a look at the ListChannels output and check the following fields for the inactive peers?

"static_remote_key": true,
"commitment_type": "STATIC_REMOTE_KEY",

I'm not sure about what the peers are running but I have a few LNBIG channels and all are inactive. Most of the inactive channels show:

"static_remote_key": false,
"commitment_type": "LEGACY"

However, I noticed two additional inactive channels (that weren't inactive as of my last message) and those both had

"static_remote_key": true,
"commitment_type": "STATIC_REMOTE_KEY",

I tried restarting lnd to see if those would reactivate, and upon restarting it looks like one of those channels was force closed.

2020-12-17 10:04:44.166 [ERR] HSWC: ChannelLink(659015:287:1): failing link: ChannelPoint(1c15845afcb4fc731e6c550354729af5414fad41e03a1b7d0afc0efef6d6ca0f:1): unable
 to accept new commitment: rejected commitment: commit_height=107, invalid_commit_sig=3045022100e05c6f4ba1ec5c509bfbba99e36bcca6226e5728a29f1589bcc01db4e5a1e38902202
7e8bc873217cd3da3ac7d8d0a193698240cd5a10713db6b91e882d7110b3e88, commit_tx=02000000010fcad6f6fe0efc0a7d1b3ae041ad4f41f59a725403556c1e73fcb4fc5a84151c0100000000a2261d
8003b9e4050000000000160014bb5def9ea9fb2c3e4ebdf8a6c0ec7032e0b290cc95b7060000000000220020e4f4b29998c51928d3cb274d128112116bf2299c133618f54dffa8f0e75516ca5378110000000
000220020bf42ad54f7e633e0460fdd9ec13ba06af9f7c77f49af7db9ba857d1d9fd3388081718820, sig_hash=2b71933252efe4a0c27061fb1208a56e38506179ae0245b63527cf85c7ae9249 with err
or: invalid commitment

So I'm not sure what's going on here, it may be multiple issues. Apologies if I'm hijacking this one but I didn't want to open duplicate issues.

@Crypt-iQ
Copy link
Collaborator

@sangaman do you have any more logs from the channel where you received invalid commitment? I believe that specific case is related to the issue I linked above. I can't speak to the other channels though.

@sangaman
Copy link
Contributor

@sangaman do you have any more logs from the channel where you received invalid commitment? I believe that specific case is related to the issue I linked above. I can't speak to the other channels though.

I put the relevant log lines I could find in that issue to try to keep them separate in case I am in fact dealing with unrelated issues here simultaneously.

@sangaman
Copy link
Contributor

Half my channels are still inactive, is there hope to recover them or should I force close them? I'd be happy to help debug and provide logs, and would certainly rather keep the channels, but am currently in limbo and unsure how to proceed.

@Roasbeef
Copy link
Member

Closing due to inactivity, we have another issue that's tracking the root cause (funding locked vs chan reest).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
p2p Code related to the peer-to-peer behaviour server
Projects
None yet
Development

No branches or pull requests

8 participants