lnd: New channel with ACQIN is not active

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?

About this issue

Original URL
State: closed
Created 4 years ago
Comments: 34 (28 by maintainers)

Most upvoted comments

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 (https://github.com/ACINQ/eclair/pull/1563) but AFAIK lnd <-> c-lightning will also have this issue, so it’s worth keeping an issue open until that is fixed.

t-bast on Dec 16, 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 on Dec 1, 2020

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

Roasbeef on Sep 15, 2020

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 on Sep 15, 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).

t-bast on Sep 7, 2020

Interesting, I don’t know what these errors internally mean to lnd…let’s see what the experts say 😉

t-bast on Sep 1, 2020

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

Roasbeef on Sep 1, 2020