lnd: A LND worked very slowly and the endless repetition of log lines

Background

LND-12 executed API and CLI commands very very slowly (may be 10-20 seconds for one API command or getinfo command from cli interface). I didn’t found high CPU usage. When i saw in logs (tail -f ...) i found the endless repetition of log lines (cyclic repetitions of some logging lines and nothing else). After LND restarting it works as expected.

Your environment

  • version of lnd - 0.12.0-beta.rc1 commit=v0.12.0-beta.rc1-18-gcc0321d1881ed23c9608cf898af2e2a7b347304a

Actual behaviour

log files:

2021-01-02 02:21:44.409 [INF] HSWC: Removing channel link with ChannelID(672302810cf0467447ab6665fb7dfcc38dbb4624d8ee013ccd27e3840f42faba)
2021-01-02 02:21:44.409 [INF] HSWC: ChannelLink(597053:1913:0): starting
2021-01-02 02:21:44.409 [INF] HSWC: Trimming open circuits for chan_id=597053:1913:0, start_htlc_id=0
2021-01-02 02:21:44.409 [INF] HSWC: Adding live link chan_id=672302810cf0467447ab6665fb7dfcc38dbb4624d8ee013ccd27e3840f42faba, short_chan_id=597053:1913:0
2021-01-02 02:21:44.409 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(bafa420f84e327cd3c01eed82446bb8dc3fc7dfb6566ab477446f00c81022367:0)
2021-01-02 02:21:44.409 [INF] HSWC: ChannelLink(597053:1913:0): HTLC manager started, bandwidth=0 mSAT
2021-01-02 02:21:44.409 [INF] HSWC: ChannelLink(597053:1913:0): attempting to re-resynchronize
2021-01-02 02:21:44.409 [INF] PEER: Negotiated chan series queries with 03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f
2021-01-02 02:21:44.410 [INF] DISC: Creating new GossipSyncer for peer=03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f
2021-01-02 02:21:44.467 [INF] PEER: unable to read message from 03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f@174.230.11.84:11116: EOF
2021-01-02 02:21:44.467 [INF] PEER: disconnecting 03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f@174.230.11.84:11116, reason: read handler closed
2021-01-02 02:21:44.567 [INF] DISC: Removing GossipSyncer for peer=03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f
2021-01-02 02:21:44.567 [INF] HSWC: Removing channel link with ChannelID(672302810cf0467447ab6665fb7dfcc38dbb4624d8ee013ccd27e3840f42faba)
2021-01-02 02:21:44.567 [INF] HSWC: ChannelLink(597053:1913:0): stopping
2021-01-02 02:21:44.567 [WRN] HSWC: ChannelLink(597053:1913:0): error when syncing channel states: link shutting down
2021-01-02 02:21:44.567 [INF] HSWC: ChannelLink(597053:1913:0): exited
2021-01-02 02:21:46.705 [INF] SRVR: New inbound connection from 174.230.11.84:8263
2021-01-02 02:21:46.705 [INF] SRVR: Finalizing connection to 03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f@174.230.11.84:8263, inbound=true
2021-01-02 02:21:46.705 [INF] PEER: Legacy channel open with peer: 03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f, downgrading static remote required feature bit to optional
2021-01-02 02:21:46.708 [INF] PEER: NodeKey(03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f) loading ChannelPoint(bafa420f84e327cd3c01eed82446bb8dc3fc7dfb6566ab477446f00c81022367:0)
2021-01-02 02:21:46.708 [INF] HSWC: Removing channel link with ChannelID(672302810cf0467447ab6665fb7dfcc38dbb4624d8ee013ccd27e3840f42faba)
2021-01-02 02:21:46.708 [INF] HSWC: ChannelLink(597053:1913:0): starting
2021-01-02 02:21:46.708 [INF] HSWC: Trimming open circuits for chan_id=597053:1913:0, start_htlc_id=0
2021-01-02 02:21:46.708 [INF] HSWC: Adding live link chan_id=672302810cf0467447ab6665fb7dfcc38dbb4624d8ee013ccd27e3840f42faba, short_chan_id=597053:1913:0
2021-01-02 02:21:46.708 [INF] HSWC: ChannelLink(597053:1913:0): HTLC manager started, bandwidth=0 mSAT
2021-01-02 02:21:46.709 [INF] HSWC: ChannelLink(597053:1913:0): attempting to re-resynchronize
2021-01-02 02:21:46.708 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(bafa420f84e327cd3c01eed82446bb8dc3fc7dfb6566ab477446f00c81022367:0)
2021-01-02 02:21:46.709 [INF] PEER: Negotiated chan series queries with 03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f
2021-01-02 02:21:46.709 [INF] DISC: Creating new GossipSyncer for peer=03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f
2021-01-02 02:21:46.767 [INF] PEER: unable to read message from 03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f@174.230.11.84:8263: EOF
2021-01-02 02:21:46.767 [INF] PEER: disconnecting 03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f@174.230.11.84:8263, reason: read handler closed
2021-01-02 02:21:46.867 [INF] DISC: Removing GossipSyncer for peer=03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f
2021-01-02 02:21:46.867 [INF] HSWC: Removing channel link with ChannelID(672302810cf0467447ab6665fb7dfcc38dbb4624d8ee013ccd27e3840f42faba)
2021-01-02 02:21:46.867 [INF] HSWC: ChannelLink(597053:1913:0): stopping
2021-01-02 02:21:46.867 [WRN] HSWC: ChannelLink(597053:1913:0): error when syncing channel states: link shutting down
2021-01-02 02:21:46.867 [INF] HSWC: ChannelLink(597053:1913:0): exited
2021-01-02 02:21:49.015 [INF] SRVR: New inbound connection from 174.230.11.84:8286
2021-01-02 02:21:49.015 [INF] SRVR: Finalizing connection to 03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f@174.230.11.84:8286, inbound=true
2021-01-02 02:21:49.015 [INF] PEER: Legacy channel open with peer: 03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f, downgrading static remote required feature bit to optional
2021-01-02 02:21:49.018 [INF] PEER: NodeKey(03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f) loading ChannelPoint(bafa420f84e327cd3c01eed82446bb8dc3fc7dfb6566ab477446f00c81022367:0)
2021-01-02 02:21:49.018 [INF] HSWC: Removing channel link with ChannelID(672302810cf0467447ab6665fb7dfcc38dbb4624d8ee013ccd27e3840f42faba)
2021-01-02 02:21:49.018 [INF] HSWC: ChannelLink(597053:1913:0): starting
2021-01-02 02:21:49.018 [INF] HSWC: Trimming open circuits for chan_id=597053:1913:0, start_htlc_id=0
2021-01-02 02:21:49.019 [INF] HSWC: Adding live link chan_id=672302810cf0467447ab6665fb7dfcc38dbb4624d8ee013ccd27e3840f42faba, short_chan_id=597053:1913:0
2021-01-02 02:21:49.019 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(bafa420f84e327cd3c01eed82446bb8dc3fc7dfb6566ab477446f00c81022367:0)
2021-01-02 02:21:49.019 [INF] PEER: Negotiated chan series queries with 03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f
2021-01-02 02:21:49.019 [INF] HSWC: ChannelLink(597053:1913:0): HTLC manager started, bandwidth=0 mSAT
2021-01-02 02:21:49.019 [INF] HSWC: ChannelLink(597053:1913:0): attempting to re-resynchronize
2021-01-02 02:21:49.019 [INF] DISC: Creating new GossipSyncer for peer=03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f
2021-01-02 02:21:49.071 [INF] PEER: unable to read message from 03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f@174.230.11.84:8286: EOF
2021-01-02 02:21:49.071 [INF] PEER: disconnecting 03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f@174.230.11.84:8286, reason: read handler closed
2021-01-02 02:21:49.171 [INF] DISC: Removing GossipSyncer for peer=03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f
2021-01-02 02:21:49.171 [INF] HSWC: Removing channel link with ChannelID(672302810cf0467447ab6665fb7dfcc38dbb4624d8ee013ccd27e3840f42faba)
2021-01-02 02:21:49.171 [INF] HSWC: ChannelLink(597053:1913:0): stopping
2021-01-02 02:21:49.171 [WRN] HSWC: ChannelLink(597053:1913:0): error when syncing channel states: link shutting down
2021-01-02 02:21:49.171 [INF] HSWC: ChannelLink(597053:1913:0): exited
2021-01-02 02:21:51.306 [INF] SRVR: New inbound connection from 174.230.11.84:10854
2021-01-02 02:21:51.306 [INF] SRVR: Finalizing connection to 03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f@174.230.11.84:10854, inbound=true
2021-01-02 02:21:51.306 [INF] PEER: Legacy channel open with peer: 03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f, downgrading static remote required feature bit to optional
2021-01-02 02:21:51.309 [INF] PEER: NodeKey(03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f) loading ChannelPoint(bafa420f84e327cd3c01eed82446bb8dc3fc7dfb6566ab477446f00c81022367:0)
2021-01-02 02:21:51.309 [INF] HSWC: Removing channel link with ChannelID(672302810cf0467447ab6665fb7dfcc38dbb4624d8ee013ccd27e3840f42faba)
2021-01-02 02:21:51.309 [INF] HSWC: ChannelLink(597053:1913:0): starting
2021-01-02 02:21:51.309 [INF] HSWC: Trimming open circuits for chan_id=597053:1913:0, start_htlc_id=0
2021-01-02 02:21:51.310 [INF] HSWC: Adding live link chan_id=672302810cf0467447ab6665fb7dfcc38dbb4624d8ee013ccd27e3840f42faba, short_chan_id=597053:1913:0
2021-01-02 02:21:51.310 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(bafa420f84e327cd3c01eed82446bb8dc3fc7dfb6566ab477446f00c81022367:0)
2021-01-02 02:21:51.310 [INF] PEER: Negotiated chan series queries with 03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f
2021-01-02 02:21:51.310 [INF] DISC: Creating new GossipSyncer for peer=03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f
2021-01-02 02:21:51.310 [INF] HSWC: ChannelLink(597053:1913:0): HTLC manager started, bandwidth=0 mSAT
2021-01-02 02:21:51.310 [INF] HSWC: ChannelLink(597053:1913:0): attempting to re-resynchronize
2021-01-02 02:21:51.357 [INF] PEER: unable to read message from 03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f@174.230.11.84:10854: EOF
2021-01-02 02:21:51.357 [INF] PEER: disconnecting 03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f@174.230.11.84:10854, reason: read handler closed
2021-01-02 02:21:51.457 [INF] DISC: Removing GossipSyncer for peer=03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f
2021-01-02 02:21:51.457 [INF] HSWC: Removing channel link with ChannelID(672302810cf0467447ab6665fb7dfcc38dbb4624d8ee013ccd27e3840f42faba)
2021-01-02 02:21:51.457 [INF] HSWC: ChannelLink(597053:1913:0): stopping
2021-01-02 02:21:51.457 [WRN] HSWC: ChannelLink(597053:1913:0): error when syncing channel states: link shutting down
2021-01-02 02:21:51.457 [INF] HSWC: ChannelLink(597053:1913:0): exited
2021-01-02 02:21:53.607 [INF] SRVR: New inbound connection from 174.230.11.84:10866
2021-01-02 02:21:53.607 [INF] SRVR: Finalizing connection to 03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f@174.230.11.84:10866, inbound=true
2021-01-02 02:21:53.607 [INF] PEER: Legacy channel open with peer: 03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f, downgrading static remote required feature bit to optional
2021-01-02 02:21:53.612 [INF] PEER: NodeKey(03059e1d26cfac0c448196c2e685a932f4bfb756a6265acdb32dc7fb015895e83f) loading ChannelPoint(bafa420f84e327cd3c01eed82446bb8dc3fc7dfb6566ab477446f00c81022367:0)

And so on…

About this issue

  • Original URL
  • State: closed
  • Created 3 years ago
  • Comments: 37 (23 by maintainers)

Most upvoted comments

@Roasbeef @cfromknecht My profiles looked similar with btcd backend. I just cherry-picked #5043 onto v0.12.0 and so far so good! I’ll continue to watch it but looks very promising so far. No CPU or network spikes and getinfo is returning in about 1 second.

+2
gkrizek on Feb 18, 2021

Also appears to have fixed it for me 👍

+1
mrfelton on Feb 19, 2021

I see you closed the issue already but I wanted to say that #5043 also fixed the problem for me with bitcoind.

+1
chrisrico on Feb 19, 2021

Update: I let this sit overnight. The CPU and Network still spikes from time to time but that’s nothing new. The important thing is when the CPU is spiking to about ~75-80% the getinfo calls still return in about 2 seconds. Previously they were taking anywhere from 30-60 seconds during the spikes. I’d consider #5043 a fix for this issue, but probably best to get some bitcoind testers in there too.

+1
gkrizek on Feb 18, 2021

I’m attaching the two CPU profiles here as they don’t contain any sensitive information.

It looks to me like this is btcd specific. The JSON parsing takes up most of the CPU cycles. Do we parse a full verbose block here?

profile001 profile002

+1
guggero on Feb 4, 2021
Read more comments on GitHub
← lnd: authentication handshake failed: x509: cannot validate certificate for 127.0.0.1 because it doesn\'t contain any IP SANs"
lnd: admin.macaroon is not created when running lnd →