lnd icon indicating copy to clipboard operation
lnd copied to clipboard

Published 20 hours ago • verified publisher icon lightningnetwork

[bug]: channel inactive but online

Open mariodian opened this issue 2 years ago • 47 comments

Background

One of the channels I opened long time ago has been showing as inactive for a few weeks now. I can't find the node in lncli peers but it seems to be alive and well (it's blockstream store). I get disconnected from it every time I try connecting either automatically or manually.

Your environment

  • lncli version 0.16.99-beta commit=v0.16.0-beta-368-g753af11ed (I've had this issue with earlier commits too - as early as a few months ago)
  • Ubuntu 22.04.2 LTS (GNU/Linux 5.15.0-73-generic x86_64)
  • Bitcoin Core RPC client version v25.0.0

Steps to reproduce

$ lncli connect 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735 |  tail -f ~/.lnd/logs/bitcoin/mainnet/lnd.log

Finalizing connection to 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@127.0.0.1:49756, inbound=true
2023-06-11 14:16:10.233 [INF] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): loading ChannelPoint(3e37348c79282a149f48eae6c51548b01e0064f5e7d8903fe7f4ca911855c278:1)
2023-06-11 14:16:10.233 [INF] HSWC: ChannelLink(3e37348c79282a149f48eae6c51548b01e0064f5e7d8903fe7f4ca911855c278:1): starting
2023-06-11 14:16:10.233 [INF] HSWC: Trimming open circuits for chan_id=689862:1669:1, start_htlc_id=224
2023-06-11 14:16:10.233 [INF] HSWC: Adding live link chan_id=78c2551891caf4e73f90d8e7f564001eb04815c5e6ea489f142a28798c34373f, short_chan_id=689862:1669:1
2023-06-11 14:16:10.234 [INF] NTFN: New block epoch subscription
2023-06-11 14:16:10.233 [INF] HSWC: ChannelLink(3e37348c79282a149f48eae6c51548b01e0064f5e7d8903fe7f4ca911855c278:1): HTLC manager started, bandwidth=7819940195 mSAT
2023-06-11 14:16:10.234 [INF] HSWC: ChannelLink(3e37348c79282a149f48eae6c51548b01e0064f5e7d8903fe7f4ca911855c278:1): attempting to re-synchronize
2023-06-11 14:16:10.234 [INF] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Negotiated chan series queries
2023-06-11 14:16:10.233 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(3e37348c79282a149f48eae6c51548b01e0064f5e7d8903fe7f4ca911855c278:1)
2023-06-11 14:16:11.351 [INF] HSWC: ChannelLink(3e37348c79282a149f48eae6c51548b01e0064f5e7d8903fe7f4ca911855c278:1): received re-establishment message from remote side
2023-06-11 14:16:11.359 [INF] HSWC: ChannelLink(3e37348c79282a149f48eae6c51548b01e0064f5e7d8903fe7f4ca911855c278:1): sending 2 updates to synchronize the state
2023-06-11 14:16:12.213 [INF] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): unable to read message from peer: EOF
2023-06-11 14:16:12.213 [INF] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): disconnecting 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@127.0.0.1:49756, reason: read handler closed
2023-06-11 14:16:12.214 [INF] NTFN: Cancelling epoch notification, epoch_id=1099
2023-06-11 14:16:12.414 [INF] HSWC: ChannelLink(3e37348c79282a149f48eae6c51548b01e0064f5e7d8903fe7f4ca911855c278:1): stopping
2023-06-11 14:16:12.414 [INF] HSWC: ChannelLink(3e37348c79282a149f48eae6c51548b01e0064f5e7d8903fe7f4ca911855c278:1): exited
2023-06-11 14:16:12.414 [INF] HSWC: Removing channel link with ChannelID(78c2551891caf4e73f90d8e7f564001eb04815c5e6ea489f142a28798c34373f)

$ lncli listchannels --inactive_only

{
    "channels": [
        {
            "active": false,
            "remote_pubkey": "02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f",
            "channel_point": "3e37348c79282a149f48eae6c51548b01e0064f5e7d8903fe7f4ca911855c278:1",
            "chan_id": "758511290670186497",
            "capacity": "8000000",
            "local_balance": "7890518",
            "remote_balance": "99833",
            "commit_fee": "9649",
            "commit_weight": "724",
            "fee_per_kw": "13326",
            "unsettled_balance": "0",
            "total_satoshis_sent": "1909115",
            "total_satoshis_received": "1809281",
            "num_updates": "6390",
            "pending_htlcs": [
            ],
            "csv_delay": 144,
            "private": false,
            "initiator": true,
            "chan_status_flags": "ChanStatusDefault",
            "local_chan_reserve_sat": "80000",
            "remote_chan_reserve_sat": "80000",
            "static_remote_key": true,
            "commitment_type": "STATIC_REMOTE_KEY",
            "lifetime": "325301",
            "uptime": "0",
            "close_address": "",
            "push_amount_sat": "0",
            "thaw_height": 0,
            "local_constraints": {
                "csv_delay": 144,
                "chan_reserve_sat": "80000",
                "dust_limit_sat": "573",
                "max_pending_amt_msat": "18446744073709551615",
                "min_htlc_msat": "0",
                "max_accepted_htlcs": 30
            },
            "remote_constraints": {
                "csv_delay": 961,
                "chan_reserve_sat": "80000",
                "dust_limit_sat": "546",
                "max_pending_amt_msat": "7920000000",
                "min_htlc_msat": "1",
                "max_accepted_htlcs": 483
            },
            "alias_scids": [
            ],
            "zero_conf": false,
            "zero_conf_confirmed_scid": "0"
        }
    ]
}

mariodian avatar Jun 11 '23 06:06 mariodian

Thank you, I think the interesting line is

2023-06-11 14:16:11.359 [INF] HSWC: ChannelLink(3e37348c79282a149f48eae6c51548b01e0064f5e7d8903fe7f4ca911855c278:1): sending 2 updates to synchronize the state

Could you enable debug logs (lncli debuglevel --level debug), repeat the connection process and report those logs as well?

bitromortac avatar Jun 12 '23 08:06 bitromortac

Thank you, I think the interesting line is

2023-06-11 14:16:11.359 [INF] HSWC: ChannelLink(3e37348c79282a149f48eae6c51548b01e0064f5e7d8903fe7f4ca911855c278:1): sending 2 updates to synchronize the state

Indeed, although I have no idea what a zombie index means:

2023-06-13 15:11:14.429 [INF] HSWC: ChannelLink(3e37348c79282a149f48eae6c51548b01e0064f5e7d8903fe7f4ca911855c278:1): sending 2 updates to synchronize the state
2023-06-13 15:11:14.432 [DBG] HSWC: ChannelLink(3e37348c79282a149f48eae6c51548b01e0064f5e7d8903fe7f4ca911855c278:1): loaded 0 fwd pks
2023-06-13 15:11:14.432 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Sending UpdateFee(chan_id=78c2551891caf4e73f90d8e7f564001eb04815c5e6ea489f142a28798c34373f, fee_update_sat=253) to 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.433 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Sending CommitSig(chan_id=78c2551891caf4e73f90d8e7f564001eb04815c5e6ea489f142a28798c34373f, num_htlcs=0) to 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.433 [DBG] DISC: Removed edge with chan_id=769110:588:1 from zombie index
2023-06-13 15:11:14.434 [DBG] DISC: Got ChannelUpdate for edge not found in graph(shortChanID=845645388077334529), saving for reprocessing later
2023-06-13 15:11:14.442 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Received ChannelAnnouncement(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=832311610619068416) from 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.443 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Received ChannelUpdate(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=832311610619068416, mflags=00000001, cflags=00000001, update_time=2023-05-31 19:33:47 +0800 CST) from 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.443 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Received ChannelAnnouncement(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=762972009373696001) from 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.443 [DBG] DISC: Processing ChannelAnnouncement: peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, short_chan_id=832311610619068416
2023-06-13 15:11:14.443 [DBG] CRTR: Waiting for dependent on job=lnwire.ChannelUpdate, scid=832311610619068416
2023-06-13 15:11:14.445 [DBG] DISC: Processing ChannelUpdate: peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, short_chan_id=832311610619068416, 
2023-06-13 15:11:14.444 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Received ChannelUpdate(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=762972009373696001, mflags=00000001, cflags=00000001, update_time=2023-05-31 19:22:01 +0800 CST) from 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.445 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Received ChannelUpdate(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=645626630834814977, mflags=00000001, cflags=00000000, update_time=2023-06-01 01:55:29 +0800 CST) from 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.446 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Received ChannelUpdate(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=850594290052235264, mflags=00000001, cflags=00000001, update_time=2023-06-01 11:44:57 +0800 CST) from 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.444 [DBG] DISC: Processing ChannelAnnouncement: peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, short_chan_id=762972009373696001
2023-06-13 15:11:14.446 [DBG] DISC: Processing ChannelUpdate: peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, short_chan_id=645626630834814977, 
2023-06-13 15:11:14.446 [DBG] CRTR: Waiting for dependent on job=lnwire.ChannelUpdate, scid=762972009373696001
2023-06-13 15:11:14.446 [DBG] DISC: Processing ChannelUpdate: peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, short_chan_id=850594290052235264, 
2023-06-13 15:11:14.446 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Received ChannelUpdate(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=848805384547860481, mflags=00000001, cflags=00000000, update_time=2023-06-01 21:50:29 +0800 CST) from 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.447 [DBG] DISC: Removed edge with chan_id=756983:1378:0 from zombie index
2023-06-13 15:11:14.447 [DBG] DISC: Got ChannelUpdate for edge not found in graph(shortChanID=832311610619068416), saving for reprocessing later
2023-06-13 15:11:14.447 [DBG] DISC: Processing ChannelUpdate: peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, short_chan_id=848805384547860481, 
2023-06-13 15:11:14.447 [DBG] DISC: Processing ChannelUpdate: peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, short_chan_id=762972009373696001, 
2023-06-13 15:11:14.449 [DBG] DISC: Removed edge with chan_id=587194:1137:1 from zombie index
2023-06-13 15:11:14.449 [DBG] DISC: Ignored stale edge policy for short_chan_id(848805384547860481): peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, msg=ChannelUpdate, is_remote=true
2023-06-13 15:11:14.449 [DBG] DISC: Got ChannelUpdate for edge not found in graph(shortChanID=645626630834814977), saving for reprocessing later
2023-06-13 15:11:14.450 [DBG] DISC: Removed edge with chan_id=773611:2698:0 from zombie index
2023-06-13 15:11:14.450 [DBG] DISC: Got ChannelUpdate for edge not found in graph(shortChanID=850594290052235264), saving for reprocessing later
2023-06-13 15:11:14.451 [DBG] DISC: Removed edge with chan_id=693919:2121:1 from zombie index
2023-06-13 15:11:14.452 [DBG] DISC: Got ChannelUpdate for edge not found in graph(shortChanID=762972009373696001), saving for reprocessing later
2023-06-13 15:11:14.458 [DBG] HSWC: Sent 1909115 satoshis and received 1809281 satoshis in the last 10 seconds (639.000000 tx/sec)
2023-06-13 15:11:14.486 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Received ChannelUpdate(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=823661752678547457, mflags=00000001, cflags=00000001, update_time=2023-06-02 09:10:35 +0800 CST) from 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.486 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Received ChannelUpdate(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=801991477978726402, mflags=00000001, cflags=00000001, update_time=2023-06-02 20:50:54 +0800 CST) from 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.487 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Received ChannelUpdate(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=755117098304667649, mflags=00000001, cflags=00000001, update_time=2023-06-02 22:28:36 +0800 CST) from 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.487 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Received ChannelUpdate(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=823864062870814720, mflags=00000001, cflags=00000001, update_time=2023-06-03 06:51:03 +0800 CST) from 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.488 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Received ChannelUpdate(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=745207199950766080, mflags=00000001, cflags=00000001, update_time=2023-06-04 03:52:20 +0800 CST) from 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.487 [DBG] DISC: Processing ChannelUpdate: peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, short_chan_id=823661752678547457, 
2023-06-13 15:11:14.487 [DBG] DISC: Processing ChannelUpdate: peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, short_chan_id=801991477978726402, 
2023-06-13 15:11:14.487 [DBG] DISC: Processing ChannelUpdate: peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, short_chan_id=755117098304667649, 
2023-06-13 15:11:14.489 [DBG] DISC: Ignored stale edge policy for short_chan_id(755117098304667649): peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, msg=ChannelUpdate, is_remote=true
2023-06-13 15:11:14.488 [DBG] DISC: Processing ChannelUpdate: peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, short_chan_id=823864062870814720, 
2023-06-13 15:11:14.488 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Received ChannelUpdate(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=809695755924406272, mflags=00000001, cflags=00000001, update_time=2023-06-04 07:32:18 +0800 CST) from 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.490 [DBG] DISC: Processing ChannelUpdate: peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, short_chan_id=809695755924406272, 
2023-06-13 15:11:14.488 [DBG] DISC: Processing ChannelUpdate: peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, short_chan_id=745207199950766080, 
2023-06-13 15:11:14.488 [DBG] DISC: Ignored stale edge policy for short_chan_id(823661752678547457): peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, msg=ChannelUpdate, is_remote=true
2023-06-13 15:11:14.488 [DBG] DISC: Ignored stale edge policy for short_chan_id(801991477978726402): peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, msg=ChannelUpdate, is_remote=true
2023-06-13 15:11:14.491 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Received ChannelUpdate(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=865073758518837249, mflags=00000001, cflags=00000001, update_time=2023-06-04 07:32:18 +0800 CST) from 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.491 [DBG] DISC: Processing ChannelUpdate: peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, short_chan_id=865073758518837249, 
2023-06-13 15:11:14.491 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Received ChannelUpdate(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=822031176893267970, mflags=00000001, cflags=00000000, update_time=2023-06-04 07:32:18 +0800 CST) from 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.492 [DBG] DISC: Processing ChannelUpdate: peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, short_chan_id=822031176893267970, 
2023-06-13 15:11:14.492 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Received ChannelUpdate(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=838683280479420417, mflags=00000001, cflags=00000001, update_time=2023-06-04 07:32:18 +0800 CST) from 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.492 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Received ChannelUpdate(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=861741138826100736, mflags=00000001, cflags=00000000, update_time=2023-06-04 07:32:19 +0800 CST) from 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.493 [DBG] DISC: Processing ChannelUpdate: peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, short_chan_id=861741138826100736, 
2023-06-13 15:11:14.492 [DBG] DISC: Processing ChannelUpdate: peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, short_chan_id=838683280479420417, 
2023-06-13 15:11:14.492 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Received ChannelUpdate(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=758988478675550209, mflags=00000001, cflags=00000000, update_time=2023-06-04 07:32:18 +0800 CST) from 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.493 [DBG] DISC: Processing ChannelUpdate: peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, short_chan_id=758988478675550209, 
2023-06-13 15:11:14.493 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Received ChannelUpdate(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=789811088221274112, mflags=00000001, cflags=00000000, update_time=2023-06-04 07:32:18 +0800 CST) from 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.494 [DBG] DISC: Processing ChannelUpdate: peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, short_chan_id=789811088221274112, 
2023-06-13 15:11:14.494 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Received ChannelUpdate(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=842818543729246209, mflags=00000001, cflags=00000000, update_time=2023-06-04 07:32:19 +0800 CST) from 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.494 [DBG] DISC: Processing ChannelUpdate: peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, short_chan_id=842818543729246209, 
2023-06-13 15:11:14.495 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Received ChannelUpdate(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=812083895183409153, mflags=00000001, cflags=00000001, update_time=2023-06-04 07:32:18 +0800 CST) from 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.495 [DBG] DISC: Processing ChannelUpdate: peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, short_chan_id=812083895183409153, 
2023-06-13 15:11:14.495 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Received ChannelUpdate(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=723467656115781632, mflags=00000001, cflags=00000000, update_time=2023-06-04 07:32:19 +0800 CST) from 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.495 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Received ChannelUpdate(chain_hash=000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f, short_chan_id=734188993981841408, mflags=00000001, cflags=00000001, update_time=2023-06-04 07:32:18 +0800 CST) from 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:11:14.495 [DBG] DISC: Processing ChannelUpdate: peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, short_chan_id=723467656115781632, 
2023-06-13 15:11:14.496 [DBG] DISC: Processing ChannelUpdate: peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, short_chan_id=734188993981841408, 
2023-06-13 15:11:14.497 [DBG] DISC: Removed edge with chan_id=749300:2720:0 from zombie index
2023-06-13 15:11:14.498 [DBG] DISC: Got ChannelUpdate for edge not found in graph(shortChanID=823864062870814720), saving for reprocessing later
2023-06-13 15:11:14.497 [DBG] DISC: Ignored stale edge policy for short_chan_id(838683280479420417): peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, msg=ChannelUpdate, is_remote=true
2023-06-13 15:11:14.497 [DBG] DISC: Ignored stale edge policy for short_chan_id(745207199950766080): peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, msg=ChannelUpdate, is_remote=true
2023-06-13 15:11:14.497 [DBG] DISC: Ignored stale edge policy for short_chan_id(865073758518837249): peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, msg=ChannelUpdate, is_remote=true
2023-06-13 15:11:14.497 [DBG] DISC: Ignored stale edge policy for short_chan_id(822031176893267970): peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, msg=ChannelUpdate, is_remote=true
2023-06-13 15:11:14.497 [DBG] DISC: Ignored stale edge policy for short_chan_id(861741138826100736): peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, msg=ChannelUpdate, is_remote=true
2023-06-13 15:11:14.497 [DBG] DISC: Ignored stale edge policy for short_chan_id(842818543729246209): peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, msg=ChannelUpdate, is_remote=true
2023-06-13 15:11:14.497 [DBG] DISC: Ignored stale edge policy for short_chan_id(758988478675550209): peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, msg=ChannelUpdate, is_remote=true
2023-06-13 15:11:14.497 [DBG] DISC: Ignored stale edge policy for short_chan_id(789811088221274112): peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, msg=ChannelUpdate, is_remote=true
2023-06-13 15:11:14.498 [DBG] DISC: Ignored stale edge policy for short_chan_id(812083895183409153): peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, msg=ChannelUpdate, is_remote=true
2023-06-13 15:11:14.498 [DBG] DISC: Ignored stale edge policy for short_chan_id(734188993981841408): peer=02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735, msg=ChannelUpdate, is_remote=true
2023-06-13 15:11:14.499 [DBG] DISC: Removed edge with chan_id=736414:1028:0 from zombie index
2023-06-13 15:11:14.499 [DBG] DISC: Got ChannelUpdate for edge not found in graph(shortChanID=809695755924406272), saving for reprocessing later
2023-06-13 15:11:14.500 [DBG] DISC: Removed edge with chan_id=657990:2372:0 from zombie index
2023-06-13 15:11:14.500 [DBG] DISC: Got ChannelUpdate for edge not found in graph(shortChanID=723467656115781632), saving for reprocessing later

More in the attached file:

lnd_log.txt

// edit: updated the log file going from peer connect all the way to the exit. there may be some unrelated stuff

mariodian avatar Jun 13 '23 07:06 mariodian

Great, I think you can ignore the zombie index logs. It seems like your peer doesn't like the fee update for the channel which is sent here:

2023-06-13 15:11:14.432 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Sending UpdateFee(chan_id=78c2551891caf4e73f90d8e7f564001eb04815c5e6ea489f142a28798c34373f, fee_update_sat=253) to 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735

and rejected here with a warning:

2023-06-13 15:27:54.004 [DBG] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): Received Warning(chan_id=78c2551891caf4e73f90d8e7f564001eb04815c5e6ea489f142a28798c34373f, err=update_fee 253 outside range 1766-67478 (currently 13326)) from 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f@giexynrrloc2fewstcybenljdksidtglfydecbellzkl63din6w73eid.onion:9735
2023-06-13 15:27:54.004 [INF] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): unable to read message from peer: EOF
2023-06-13 15:27:54.005 [INF] PEER: Peer(02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f): disconnecting

Do you use any custom fee estimation, or could you look up any fee related settings in your lnd.conf?

bitromortac avatar Jun 13 '23 11:06 bitromortac

I use charge-lnd to change fees once an hour based on various scenarios. However, that should be unrelated no? (meanwhile I set correct fees from the range above just to be safe)

And no, I don't use any custom fee estimation as far as I'm aware.

Fee related settings in ~/.lnd/lnd.conf:

bitcoin.basefee=0
bitcoin.feerate=100
bitcoin.minhtlc=1000

Fee report for the node:

$ lncli feereport

lncli feereport
{
    "channel_fees": [
        {
            "chan_id": "758511290670186497",
            "channel_point": "3e37348c79282a149f48eae6c51548b01e0064f5e7d8903fe7f4ca911855c278:1",
            "base_fee_msat": "0",
            "fee_per_mil": "2587",
            "fee_rate": 0.002587
        }
...

I don't know where it's getting the number 253 from.

BTW, after setting the fees from the correct range I'm getting this message:

[DBG] SRVR: Scheduling connection re-establishment to persistent peer 02df5ffe895c778e10f7742a6c5b8a0cefbe9465df58b92fadeb883752c8107c8f in 1h3m0s

So I guess I have to wait for now?

mariodian avatar Jun 13 '23 12:06 mariodian

I see the number 253 mentioned in logs for another node but I have no idea where it's set or where it's coming from or even how to change it:

cat ~/.lnd/logs/bitcoin/mainnet/lnd.log | grep 253

2023-06-13 15:27:50.092 [DBG] DISC: Ignored stale edge policy for short_chan_id(862383253637169153): peer=03cde60a6323f7122d5178255766e38114b4722ede08f7c9e0c5df9b912cc201d6@34.65.85.39:9745, msg=ChannelUpdate, is_remote=true
 feePerKw: (chainfee.SatPerKWeight) 253 sat/kw,

mariodian avatar Jun 13 '23 12:06 mariodian

I think this is about your node sending an automatic UpdateFee (this is a protocol message https://github.com/lightning/bolts/blob/master/02-peer-protocol.md#updating-fees-update_fee one can't send manually or via other tools). There may be an issue with fee estimation of your backend. Perhaps reporting bitcoin-cli getmempoolinfo and bitcoin-cli estimatesmartfee 1 gives more info.

bitromortac avatar Jun 13 '23 13:06 bitromortac

This are the outputs for the commands:

$ bitcoin-cli getmempoolinfo
{
  "loaded": true,
  "size": 112634,
  "bytes": 54353252,
  "usage": 295491120,
  "total_fee": 4.60670316,
  "maxmempool": 300000000,
  "mempoolminfee": 0.00005765,
  "minrelaytxfee": 0.00001000,
  "incrementalrelayfee": 0.00001000,
  "unbroadcastcount": 0,
  "fullrbf": true
}

$ bitcoin-cli estimatesmartfee 1
{
  "feerate": 0.00029702,
  "blocks": 2
}

I don't have any fee related settings in ~/.bitcoin/bitcoin.conf though. I do have mempoolfullrbf=1 but that shouldn't have any effect on the fee estimate, no?

Not sure if it helps, I do run these services but I don't think any of those provide fee estimate for lnd by default: electrs, lnbits, btcpayserver, thunderhub

mariodian avatar Jun 13 '23 13:06 mariodian

@mariodian I seem to be in the same situation as yourself, with possibly 2-3 channels marked as inactive. Have you had any luck sorting this out? I'm on the latest version of Umbrel OS with LND 0.16.3-beta

adamteale avatar Jun 22 '23 12:06 adamteale

@adamteale no idea, how to solve this.

mariodian avatar Jun 22 '23 12:06 mariodian

@mariodian @bitromortac in case it is of any use to you:

bitcoin-cli estimatesmartfee 1 

{
  "feerate": 0.00037909,
  "blocks": 2
}

bitcoin-cli getmempoolinfo

{
  "loaded": true,
  "size": 116314,
  "bytes": 41678984,
  "usage": 249162752,
  "total_fee": 4.35632783,
  "maxmempool": 300000000,
  "mempoolminfee": 0.00005154,
  "minrelaytxfee": 0.00001000,
  "incrementalrelayfee": 0.00001000,
  "unbroadcastcount": 0,
  "fullrbf": true
}

A snippet from the lnd logs (i've purposely altered any channel/node hash to try to hide it here):

2023-06-20 15:05:45.693 [INF] PEER: Peer(02e1dad4d396696cb207a524bdf595f1a2e6792d7b990f18cef1ebd1b567bb110f): Loading ChannelPoint(600a54e257612992513b8bbb629379b7c2b441189ee7fd7e5805a53cbb1396d4:0), isPending=false
2023-06-20 15:05:45.695 [INF] HSWC: ChannelLink(600a54e257612992513b8bbb629379b7c2b441189ee7fd7e5805a53cbb1396d4:0): starting
2023-06-20 15:05:45.695 [INF] HSWC: Trimming open circuits for chan_id=785297:1440:0, start_htlc_id=4572
2023-06-20 15:05:45.695 [INF] HSWC: Adding live link chan_id=d49616bb2ca505587efde79e1841b4c2b7799362bb8b3b5192296157e2540a60, short_chan_id=785297:1440:0
2023-06-20 15:05:45.695 [INF] NTFN: New block epoch subscription
2023-06-20 15:05:45.695 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(600a54e257612992513b8bbb629379b7c2b441189ee7fd7e5805a53cbb1396d4:0)
2023-06-20 15:05:45.695 [INF] HSWC: ChannelLink(600a54e257612992513b8bbb629379b7c2b441189ee7fd7e5805a53cbb1396d4:0): HTLC manager started, bandwidth=1218607184 mSAT
2023-06-20 15:05:45.695 [INF] HSWC: ChannelLink(600a54e257612992513b8bbb629379b7c2b441189ee7fd7e5805a53cbb1396d4:0): attempting to re-synchronize
2023-06-20 15:05:45.696 [INF] PEER: Peer(02e1dad4d396696cb207a524bdf595f1a2e6792d7b990f18cef1ebd1b567bb110f): Negotiated chan series queries
2023-06-20 15:05:45.696 [INF] DISC: Creating new GossipSyncer for peer=02e1dad4d396696cb207a524bdf595f1a2e6792d7b990f18cef1ebd1b567bb110f
2023-06-20 15:05:45.723 [WRN] DISC: ignoring remote ChannelAnnouncement for own channel
2023-06-20 15:05:45.839 [ERR] DISC: unable to validate channel update announcement for short_chan_id=(lnwire.ShortChannelID) 795179:3754:0
: invalid max htlc for channel update (*lnwire.ChannelUpdate)(0x4013d8e2c0)({
 Signature: (lnwire.Sig) (len=64 cap=64) {
  00000000  3f 55 96 45 2e 88 96 ef  9a a7 7b 53 f8 7d 70 f3  |?U.E......zS.}p.|
  00000010  54 da 06 3d 1b db 5e 27  53 ea e3 4f 0d 36 57 f9  |T..=..^'S..O.6W.|
  00000020  41 8a 8b ec df cd 40 9c  d3 8f c5 08 b5 66 5f e5  |[email protected]_.|
  00000030  23 b6 c1 c6 c1 b6 43 d0  5a 90 9e 88 a8 36 a0 aa  |#.....C.Z....6..|
 },
 ChainHash: (chainhash.Hash) (len=32 cap=32) 000000000019d6689c085ae155831e934ff763ae46a2a6c172b3f1c60a8ce26f,
 ShortChannelID: (lnwire.ShortChannelID) 795179:3754:0,
 Timestamp: (uint32) 1687263262,
 MessageFlags: (lnwire.ChanUpdateMsgFlags) 00000001,
 ChannelFlags: (lnwire.ChanUpdateChanFlags) 00000000,
 TimeLockDelta: (uint16) 34,
 HtlcMinimumMsat: (lnwire.MilliSatoshi) 1 mSAT,
 BaseFee: (uint32) 3042,
 FeeRate: (uint32) 1156,
 HtlcMaximumMsat: (lnwire.MilliSatoshi) 0 mSAT,
 ExtraOpaqueData: (lnwire.ExtraOpaqueData) {
 }
})

2023-06-20 15:05:46.144 [INF] HSWC: ChannelLink(600a54e257612992513b8bbb629379b7c2b441189ee7fd7e5805a53cbb1396d4:0): received re-establishment message from remote side
2023-06-20 15:05:46.148 [INF] HSWC: ChannelLink(600a54e257612992513b8bbb629379b7c2b441189ee7fd7e5805a53cbb1396d4:0): sending 3 updates to synchronize the state
2023-06-20 15:05:46.149 [INF] DISC: GossipSyncer(02e1dad4d396696cb207a524bdf595f1a2e6792d7b990f18cef1ebd1b567bb110f): applying new update horizon: start=2106-02-07 06:28:15 +0000 UTC, end=2242-03-16 12:56:30 +0000 UTC, backlog_size=0
2023-06-20 15:05:46.766 [INF] DISC: Received new remote announcement signature for 785297:1440:0
2023-06-20 15:05:47.150 [INF] PEER: Peer(02e1dad4d396696cb207a524bdf595f1a2e6792d7b990f18cef1ebd1b567bb110f): unable to read message from peer: EOF
2023-06-20 15:05:47.150 [WRN] HSWC: ChannelLink(600a54e257612992513b8bbb629379b7c2b441189ee7fd7e5805a53cbb1396d4:0): received warning message from peer: chan_id=d49616bb2ca505587efde79e1841b4c2b7799362bb8b3b5192296157e2540a60, err=update_fee 253 outside range 1330-55280 (currently 5272)
2023-06-20 15:05:47.150 [INF] PEER: Peer(02e1dad4d396696cb207a524bdf595f1a2e6792d7b990f18cef1ebd1b567bb110f): disconnecting 02e1dad4d396696cb207a524bdf595f1a2e6792d7b990f18cef1ebd1b567bb110f@fmspampdsqre7aiyag6le6nyi7g3xigaf26lx56bnjser2b5cs2ys6id.onion:9735, reason: read handler closed
2023-06-20 15:05:47.151 [INF] NTFN: Cancelling epoch notification, epoch_id=241
2023-06-20 15:05:47.353 [INF] DISC: Removing GossipSyncer for peer=02e1dad4d396696cb207a524bdf595f1a2e6792d7b990f18cef1ebd1b567bb110f
2023-06-20 15:05:47.353 [INF] HSWC: ChannelLink(600a54e257612992513b8bbb629379b7c2b441189ee7fd7e5805a53cbb1396d4:0): stopping
2023-06-20 15:05:47.354 [INF] HSWC: ChannelLink(600a54e257612992513b8bbb629379b7c2b441189ee7fd7e5805a53cbb1396d4:0): exited
2023-06-20 15:05:47.354 [INF] HSWC: Removing channel link with ChannelID(d49616bb2ca505587efde79e1841b4c2b7799362bb8b3b5192296157e2540a60)
2023-06-20 15:05:52.166 [WRN] HSWC: ChannelLink(d7a3ce6a137b9d8920d8301cd6082e1c7d89ae48247dec4ce5a8aaaa58e2b7d6:0): insufficient bandwidth to route htlc: 234548176 mSAT is larger than 1452913 mSAT
2023-06-20 15:05:52.166 [ERR] HSWC: insufficient bandwidth to route htlc
2023-06-20 15:05:52.167 [ERR] HSWC: Unhandled error while reforwarding htlc settle/fail over htlcswitch: insufficient bandwidth to route htlc
2023-06-20 15:05:55.041 [INF] CRTR: Processed channels=0 updates=83 nodes=6 in last 1m0.000036275s
2023-06-20 15:06:03.643 [ERR] RPCS: [/lnrpc.Lightning/GetChanInfo]: edge not found
2023-06-20 15:06:08.736 [WRN] HSWC: ChannelLink(7a6f6e2bfe03ce18fbf098a58bff8da4b093bf768c6547a2b1bb094aeaaf0ed0:1): insufficient bandwidth to route htlc: 45827135 mSAT is larger than 1355386 mSAT
2023-06-20 15:06:08.737 [ERR] HSWC: insufficient bandwidth to route htlc
2023-06-20 15:06:08.737 [ERR] HSWC: Unhandled error while reforwarding htlc settle/fail over htlcswitch: insufficient bandwidth to route htlc
2023-06-20 15:06:23.156 [ERR] RPCS: [/lnrpc.Lightning/GetChanInfo]: edge not found
2023-06-20 15:06:27.337 [ERR] NANN: Unable to retrieve chan status for Channel(a0f154923c7ffda443b24121f236231f9d2b93fe1cadb0d80f6c731378b24043:1): edge not found
2023-06-20 15:06:42.415 [ERR] RPCS: [/lnrpc.Lightning/GetChanInfo]: edge not found
2023-06-20 15:06:55.041 [INF] CRTR: Processed channels=0 updates=120 nodes=2 in last 59.999774416s
2023-06-20 15:07:01.421 [ERR] RPCS: [/lnrpc.Lightning/GetChanInfo]: edge not found
2023-06-20 15:07:21.185 [ERR] RPCS: [/lnrpc.Lightning/GetChanInfo]: edge not found
2023-06-20 15:07:27.338 [ERR] NANN: Unable to retrieve chan status for Channel(a0f154923c7ffda443b24121f236231f9d2b93fe1cadb0d80f6c731378b24043:1): edge not found
2023-06-20 15:07:41.233 [ERR] RPCS: [/lnrpc.Lightning/GetChanInfo]: edge not found
2023-06-20 15:07:55.041 [INF] CRTR: Processed channels=0 updates=171 nodes=8 in last 59.999459079s
2023-06-20 15:08:00.206 [ERR] RPCS: [/lnrpc.Lightning/GetChanInfo]: edge not found
2023-06-20 15:08:19.621 [ERR] RPCS: [/lnrpc.Lightning/GetChanInfo]: edge not found
2023-06-20 15:08:23.160 [WRN] HSWC: ChannelLink(d7a3ce6a137b9d8920d8301cd6082e1c7d89ae48247dec4ce5a8aaaa58e2b7d6:0): insufficient bandwidth to route htlc: 50008500 mSAT is larger than 1452913 mSAT
2023-06-20 15:08:23.161 [ERR] HSWC: insufficient bandwidth to route htlc
2023-06-20 15:08:23.161 [ERR] HSWC: Unhandled error while reforwarding htlc settle/fail over htlcswitch: insufficient bandwidth to route htlc
2023-06-20 15:08:27.358 [ERR] NANN: Unable to retrieve chan status for Channel(a0f154923c7ffda443b24121f236231f9d2b93fe1cadb0d80f6c731378b24043:1): edge not found
2023-06-20 15:08:38.174 [WRN] HSWC: ChannelLink(d7a3ce6a137b9d8920d8301cd6082e1c7d89ae48247dec4ce5a8aaaa58e2b7d6:0): insufficient bandwidth to route htlc: 58622897 mSAT is larger than 1452913 mSAT
2023-06-20 15:08:38.175 [ERR] HSWC: insufficient bandwidth to route htlc
2023-06-20 15:08:38.175 [ERR] HSWC: Unhandled error while reforwarding htlc settle/fail over htlcswitch: insufficient bandwidth to route htlc
2023-06-20 15:08:38.372 [ERR] RPCS: [/lnrpc.Lightning/GetChanInfo]: edge not found
2023-06-20 15:08:55.042 [INF] CRTR: Processed channels=0 updates=166 nodes=9 in last 1m0.00033709s
2023-06-20 15:08:58.553 [ERR] RPCS: [/lnrpc.Lightning/GetChanInfo]: edge not found
2023-06-20 15:08:59.147 [WRN] SRVR: Already have 1 persistent connection requests for 02e1dad4d396696cb207a524bdf595f1a2e6792d7b990f18cef1ebd1b567bb110f@10.21.21.11:51132, connecting anyway.

adamteale avatar Jun 22 '23 12:06 adamteale

Hello. This is also happening to me. It is exactly the same behavior.

PEER: Peer(xxx): unable to read message from peer: EOF
PEER: Peer(xxx): disconnecting 0334346507fbd9c36742122414e3fb9b5b4db4e432e137633bb225b1926327b51c@127.0.0.1:40126, reason: read handler closed
HSWC: ChannelLink(xxx): received warning message from peer: chan_id=xxx, err=update_fee 253 outside range 1319-64263 (currently 8149)
NTFN: Cancelling epoch notification, epoch_id=687

It is locked in a loop and this log message keeps hammering the other node every 5 seconds. I think this behavior is not good for the network if we think in scale!

UPDATE: After some research I thought it could be related to bitcoind fee estimation. So, I tried to "feeurl" config on lnd.conf. But unfortunately, it keeps the same error message.

aplnx avatar Jun 26 '23 00:06 aplnx

LND has a confirmed working fee estimator available to it but in this case it appears to not be using it?

wtogami avatar Jul 02 '23 01:07 wtogami

cc: @ziggie1984

saubyk avatar Jul 02 '23 15:07 saubyk

experiencing exact the same behaviour. Do you have any workaround in the meantime?

Dark345 avatar Jul 15 '23 12:07 Dark345

experiencing exact the same behaviour. Do you have any workaround in the meantime?

Well, there is no easy way around. I just forced close my channel since it was not useful anymore.

Please, if you are going to FC the channel, ensure that fees are very low. Check it out on mempool.space. Forcing Close costs you at least two transactions submitted. Have this in mind.

I suggest closing this issue since the real problem was revealed on issue #7666.

aplnx avatar Jul 15 '23 13:07 aplnx

similar behavior across several channels. example :

2023-07-17 13:36:19.437 [INF] SRVR: New inbound connection from 49.228.105.0:60320
2023-07-17 13:36:19.438 [INF] SRVR: Finalizing connection to 020d1617e27ac022395352f2b3774969593d3d6ddff6fb117d820a9dda8da45217@49.228.105.0:60320, inbound=true
2023-07-17 13:36:19.703 [INF] PEER: Peer(020d1617e27ac022395352f2b3774969593d3d6ddff6fb117d820a9dda8da45217): Loading ChannelPoint(cb5377202d85fb8a03c8070b25b3cd347b319e78951b67d4767e94a04c20db1a:1), isPending=false
2023-07-17 13:36:19.703 [INF] HSWC: ChannelLink(cb5377202d85fb8a03c8070b25b3cd347b319e78951b67d4767e94a04c20db1a:1): starting
2023-07-17 13:36:19.703 [INF] HSWC: Trimming open circuits for chan_id=742685:2053:1, start_htlc_id=147113
2023-07-17 13:36:19.703 [INF] HSWC: Adding live link chan_id=1adb204ca0947e76d4671b95789e317b34cdb3250b07c8038afb852d207753ca, short_chan_id=742685:2053:1
2023-07-17 13:36:19.703 [INF] NTFN: New block epoch subscription
2023-07-17 13:36:19.703 [INF] PEER: Peer(020d1617e27ac022395352f2b3774969593d3d6ddff6fb117d820a9dda8da45217): Negotiated chan series queries
2023-07-17 13:36:19.703 [INF] DISC: Creating new GossipSyncer for peer=020d1617e27ac022395352f2b3774969593d3d6ddff6fb117d820a9dda8da45217
2023-07-17 13:36:19.703 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(cb5377202d85fb8a03c8070b25b3cd347b319e78951b67d4767e94a04c20db1a:1)
2023-07-17 13:36:19.703 [INF] HSWC: ChannelLink(cb5377202d85fb8a03c8070b25b3cd347b319e78951b67d4767e94a04c20db1a:1): HTLC manager started, bandwidth=717605537 mSAT
2023-07-17 13:36:19.703 [INF] HSWC: ChannelLink(cb5377202d85fb8a03c8070b25b3cd347b319e78951b67d4767e94a04c20db1a:1): attempting to re-synchronize
2023-07-17 13:36:20.473 [WRN] DISC: ignoring remote ChannelAnnouncement for own channel
2023-07-17 13:36:20.746 [INF] DISC: Received new remote announcement signature for 742685:2053:1
2023-07-17 13:36:20.746 [INF] HSWC: ChannelLink(cb5377202d85fb8a03c8070b25b3cd347b319e78951b67d4767e94a04c20db1a:1): received re-establishment message from remote side
2023-07-17 13:36:20.757 [INF] HSWC: ChannelLink(cb5377202d85fb8a03c8070b25b3cd347b319e78951b67d4767e94a04c20db1a:1): sending 3 updates to synchronize the state
2023-07-17 13:36:21.018 [WRN] HSWC: ChannelLink(cb5377202d85fb8a03c8070b25b3cd347b319e78951b67d4767e94a04c20db1a:1): received warning message from peer: chan_id=1adb204ca0947e76d4671b95789e317b34cdb3250b07c8038afb852d207753ca, err=update_fee 253 outside range 833-4294967295 (currently 13357)
2023-07-17 13:36:21.019 [INF] PEER: Peer(020d1617e27ac022395352f2b3774969593d3d6ddff6fb117d820a9dda8da45217): unable to read message from peer: EOF
2023-07-17 13:36:21.019 [INF] PEER: Peer(020d1617e27ac022395352f2b3774969593d3d6ddff6fb117d820a9dda8da45217): disconnecting 020d1617e27ac022395352f2b3774969593d3d6ddff6fb117d820a9dda8da45217@49.228.105.0:60320, reason: read handler closed
2023-07-17 13:36:21.019 [INF] NTFN: Cancelling epoch notification, epoch_id=814
2023-07-17 13:36:21.220 [INF] DISC: Removing GossipSyncer for peer=020d1617e27ac022395352f2b3774969593d3d6ddff6fb117d820a9dda8da45217
2023-07-17 13:36:21.220 [INF] HSWC: ChannelLink(cb5377202d85fb8a03c8070b25b3cd347b319e78951b67d4767e94a04c20db1a:1): stopping
2023-07-17 13:36:21.220 [INF] HSWC: ChannelLink(cb5377202d85fb8a03c8070b25b3cd347b319e78951b67d4767e94a04c20db1a:1): exited
2023-07-17 13:36:21.220 [INF] HSWC: Removing channel link with ChannelID(1adb204ca0947e76d4671b95789e317b34cdb3250b07c8038afb852d207753ca)

the most interesting :

2023-07-17 13:36:21.018 [WRN] HSWC: ChannelLink(cb5377202d85fb8a03c8070b25b3cd347b319e78951b67d4767e94a04c20db1a:1): received warning message from peer: chan_id=1adb204ca0947e76d4671b95789e317b34cdb3250b07c8038afb852d207753ca, err=update_fee 253 outside range 833-4294967295 (currently 13357)

SunnySarahNode avatar Jul 17 '23 11:07 SunnySarahNode

020d1617e27ac022395352f2b3774969593d3d6ddff6fb117d820a9dda8da45217

Are you able to contact the node's owner? It would be interesting to know if he is using CLN implementation of the lightning network. This error is related to some incompatibility among them.

Please, check the issue 7666. Ziggie on our plebnet group is working on something that might solve this.

I had the same issue, but I waited for Mempool to clear and I forced close the channel since it was unusable and there wasn't any workaround.

aplnx avatar Jul 17 '23 12:07 aplnx

@SunnySarahNode what's interesting to find out, why your backend reports such a low feerate for the feeupdate. In your case it used 1 sats/vbyte that should not happen considering current mempool conditions did you wipe your mempool? Or could you investigate in your logs since when you are seeing these low feeupdates ? Lnd will use a blocktraget of 3 blocks for the fee-estimation. What is your fee-estimation currently:

bitcoin-cli estimatesmartfee 3

whats your bitcoin backend ?

ziggie1984 avatar Jul 17 '23 13:07 ziggie1984

@ziggie1984 I have bitcoind RPC (Bitcoin Core version v23.0.0) backend. Full, indexed.

{
  "feerate": 0.00031121,
  "blocks": 3
}

I have maxmempool=3000 in my bitcoin settings in order to prevent 7156 issue ( https://github.com/lightningnetwork/lnd/issues/7156#issuecomment-1572144164 ).

I can't reach my peers with this problem (unfortunately none of them), but I assume they have CLN. I'll let you know the details as soon as I know them.

SunnySarahNode avatar Jul 17 '23 20:07 SunnySarahNode

ok could you grep for some logs, I am especially interested when this feeupdate with those low fees emerged:

can you grep for: grep -B 1 -i "updating commit fee"

you should see something like this:

lnd.log.54088.gz-2023-07-14 07:31:49.195 [DBG] HSWC: ChannelLink(xxx:x) sampled fee rate for 3 block conf: 4781 sat/kw
lnd.log.54088.gz:2023-07-14 07:31:49.195 [INF] HSWC: ChannelLink(xxx:x): updating commit fee to 4781 sat/kw

can you look through your logs and see how the fee values behaved especially when your node proposed the 253.

Seems like you did not have any mempool issues so I am wondering where those corrupt fee-estimates come from.

ziggie1984 avatar Jul 17 '23 21:07 ziggie1984

Ok I think I know what the problem might be, could you confirm that the channel which is affected by this was almost drained ?

My general impression was that this behaviour is most likely caused by some bad backend fee-estimation. I concluded this because the example I investigated in #7666 was caused by a mempool wipe-out.

But looking at the code again it seems to me, that we can also end up in this situation when our channel is drained. Could you also take a look at this @ellemouton.

Looking in particular at this code part: https://github.com/lightningnetwork/lnd/blob/bd3f570107244688583f450653e906943f69a2f4/lnwallet/channel.go#L7339-L7355

It seems to me, that because we have a default FeeAllocation of 0.5 in combination we a drained channel (low local cap) that we end up going all the way down to the min_relay_floor (253 sat/kw). And because most of the nodes running big mempools nowdays the min_relay fee is 1 sat/vbyte.

So I think we need to be careful with the FeeAllocation, because the old fee will basically decrease over time especially when the channel is drained locally.

ziggie1984 avatar Jul 17 '23 22:07 ziggie1984

Ok I think I know what the problem might be, could you confirm that the channel which is affected by this was almost drained ?

My general impression was that this behaviour is most likely caused by some bad backend fee-estimation. I concluded this because the example I investigated in #7666 was caused by a mempool wipe-out.

But looking at the code again it seems to me, that we can also end up in this situation when our channel is drained. Could you also take a look at this @ellemouton.

Looking in particular at this code part:

https://github.com/lightningnetwork/lnd/blob/bd3f570107244688583f450653e906943f69a2f4/lnwallet/channel.go#L7339-L7355

It seems to me, that because we have a default FeeAllocation of 0.5 in combination we a drained channel (low local cap) that we end up going all the way down to the min_relay_floor (253 sat/kw). And because most of the nodes running big mempools nowdays the min_relay fee is 1 sat/vbyte.

So I think we need to be careful with the FeeAllocation, because the old fee will basically decrease over time especially when the channel is drained locally.

I can confirm that by the moment I had to force close my problematic channel, I clearly remember that it was drained. Also, the node was coinos which is CLN.

aplnx avatar Jul 18 '23 00:07 aplnx

Not sure what happened but this issue has been resolved for me. Perhaps Blockstream Store did something on their end.

mariodian avatar Jul 18 '23 02:07 mariodian

Not sure what happened but this issue has been resolved for me. Perhaps Blockstream Store did something on their end.

This can happen, if mempool fees for the CLN side go so low again, that they accept your feeupdate of 1 sat_per_vbyte, tho this can either happen if you have luck, or never when the mempool remains at high fee level.

ziggie1984 avatar Jul 18 '23 07:07 ziggie1984

Ok, I could reproduce on regtest, it is indeed a problem, working on a fix.

To prevent this from happening again, please set max-channel-fee-allocation=1 for now, this should prevent you from scaling down your fees too much from a prior state.

ziggie1984 avatar Jul 18 '23 08:07 ziggie1984

Not sure what happened but this issue has been resolved for me. Perhaps Blockstream Store did something on their end.

Blockstream Store applied a one time update_fee exception to allow the remote peer's erroneous state to be accepted just once. If their mempool is subsequently fixed then the channel will continue to work.

We found all but one of the stuck channels recovered after this one time exception. The one broken peer actually has a broken mempool right now. All of the stuck peers appear to be LND nodes.

wtogami avatar Jul 18 '23 08:07 wtogami

Not sure what happened but this issue has been resolved for me. Perhaps Blockstream Store did something on their end.

Blockstream Store applied a one time update_fee exception to allow the remote peer's erroneous state to be accepted just once. If their mempool is subsequently fixed then the channel will continue to work.

We found all but one of the stuck channels recovered after this one time exception. The one broken peer actually has a broken mempool right now. All of the stuck peers appear to be LND nodes.

one time exception, how ? by ignore-fee-limits=true ?

btweenthebars avatar Jul 19 '23 02:07 btweenthebars

Ok, I could reproduce on regtest, it is indeed a problem, working on a fix.

To prevent this from happening again, please set max-channel-fee-allocation=1 for now, this should prevent you from scaling down your fees too much from a prior state.

Is this a configuration on lnd.conf?

aplnx avatar Jul 19 '23 12:07 aplnx

Is this a configuration on lnd.conf?

Yes, have a look at the example config.

mariodian avatar Jul 20 '23 02:07 mariodian

Blockstream Store applied a one time update_fee exception to allow the remote peer's erroneous state to be accepted just once. If their mempool is subsequently fixed then the channel will continue to work. We found all but one of the stuck channels recovered after this one time exception. The one broken peer actually has a broken mempool right now. All of the stuck peers appear to be LND nodes.

one time exception, how ? by ignore-fee-limits=true ?

https://fedorapeople.org/~wtogami/a/2023/0001-DO-NOT-COMMIT-Temporary-workaround-for-LND-update_fe.patch CLN v23.05.2 users can temporarily run with this patch.

wtogami avatar Jul 20 '23 02:07 wtogami