lightningd hanging, not opening RPC port, not syncing, reducing latest block by 15

[svewa]

I have c-lightning running for over a year now, but some time maybe two month ago I noticed it stopped and would not properly start again. I tried updating to 0.7.0 and now to latest git, does not help.

config file:

log-level=io
network=bitcoin

starting lightningd:

ln@c-lightning:~$ lightning/lightningd/lightningd 
2019-05-28T22:08:01.236Z plugin-autoclean[OUT] 7b226a736f6e727063223a22322e30222c226964223a312c226d6574686f64223a226765746d616e6966657374222c22706172616d73223a7b7d7d0a0a
2019-05-28T22:08:01.236Z plugin-pay[OUT] 7b226a736f6e727063223a22322e30222c226964223a302c226d6574686f64223a226765746d616e6966657374222c22706172616d73223a7b7d7d0a0a
2019-05-28T22:08:01.297Z lightningd(3740): testing /home/ln/lightning/lightningd/lightning_channeld
2019-05-28T22:08:01.301Z lightningd(3740): testing /home/ln/lightning/lightningd/lightning_closingd
2019-05-28T22:08:01.305Z lightningd(3740): testing /home/ln/lightning/lightningd/lightning_connectd
2019-05-28T22:08:01.311Z lightningd(3740): testing /home/ln/lightning/lightningd/lightning_gossipd
2019-05-28T22:08:01.315Z lightningd(3740): testing /home/ln/lightning/lightningd/lightning_hsmd
2019-05-28T22:08:01.319Z lightningd(3740): testing /home/ln/lightning/lightningd/lightning_onchaind
2019-05-28T22:08:01.323Z lightningd(3740): testing /home/ln/lightning/lightningd/lightning_openingd
2019-05-28T22:08:01.475Z lightning_hsmd(3750): pid 3750, msgfd 17
2019-05-28T22:08:01.508Z lightning_connectd(3751): pid 3751, msgfd 20
2019-05-28T22:08:01.509Z lightning_hsmd(3750): Client: Received message 11 from client
2019-05-28T22:08:01.509Z lightning_hsmd(3750): Client: Received message 9 from client
2019-05-28T22:08:01.509Z lightning_hsmd(3750): new_client: 0
2019-05-28T22:08:01.725Z lightning_connectd(3751): Created IPv6 listener on port 9735
2019-05-28T22:08:01.725Z lightning_connectd(3751): Failed to connect 10 socket: Network is unreachable
2019-05-28T22:08:01.725Z lightning_connectd(3751): Created IPv4 listener on port 9735
2019-05-28T22:08:01.725Z lightning_connectd(3751): REPLY WIRE_CONNECTCTL_INIT_REPLY with 0 fds
2019-05-28T22:08:01.727Z lightning_gossipd(3752): pid 3752, msgfd 19
2019-05-28T22:08:01.762Z lightningd(3740): Loaded 0 HTLC signatures from DB
2019-05-28T22:08:01.766Z lightningd(3740): Loaded 0 HTLC signatures from DB
2019-05-28T22:08:01.772Z lightningd(3740): Loaded 0 HTLC signatures from DB
2019-05-28T22:08:01.779Z lightningd(3740): Loaded 0 HTLC signatures from DB
2019-05-28T22:08:01.785Z lightningd(3740): Loaded 0 HTLC signatures from DB
2019-05-28T22:08:01.789Z lightningd(3740): Loaded 0 HTLC signatures from DB
2019-05-28T22:08:01.792Z lightningd(3740): Loaded 6 channels from DB
2019-05-28T22:08:01.793Z lightningd(3740): Loading HTLCs for channel 14298
2019-05-28T22:08:01.794Z lightningd(3740): Restored 0 incoming and 0 outgoing HTLCS
2019-05-28T22:08:01.794Z lightningd(3740): Loading HTLCs for channel 15388
2019-05-28T22:08:01.795Z lightningd(3740): Restored 0 incoming and 0 outgoing HTLCS
2019-05-28T22:08:01.796Z lightningd(3740): Loading HTLCs for channel 15425
2019-05-28T22:08:01.797Z lightningd(3740): Restored 0 incoming and 0 outgoing HTLCS
2019-05-28T22:08:01.798Z lightningd(3740): Loading HTLCs for channel 18348
2019-05-28T22:08:01.799Z lightningd(3740): Restored 0 incoming and 0 outgoing HTLCS
2019-05-28T22:08:01.799Z lightningd(3740): Loading HTLCs for channel 21447
2019-05-28T22:08:01.800Z lightningd(3740): Restored 0 incoming and 0 outgoing HTLCS
2019-05-28T22:08:01.801Z lightningd(3740): Loading HTLCs for channel 23172
2019-05-28T22:08:01.801Z lightningd(3740): Restored 0 incoming and 0 outgoing HTLCS
2019-05-28T22:08:02.525Z lightning_hsmd(3750): Client: Received message 9 from client
2019-05-28T22:08:02.526Z lightning_hsmd(3750): new_client: 0
2019-05-28T22:08:02.526Z lightning_hsmd(3750): Client: Received message 10 from client
2019-05-28T22:08:02.527Z lightning_hsmd(3750): Client: Received message 10 from client
2019-05-28T22:08:02.527Z lightning_gossipd(3752): total store load time: 0 msec
2019-05-28T22:08:02.528Z lightning_hsmd(3750): Client: Received message 10 from client
2019-05-28T22:08:02.528Z lightning_gossipd(3752): gossip_store: Read 0/0/0/0 cannounce/cupdate/nannounce/cdelete from store in 1 bytes
2019-05-28T22:08:02.528Z lightning_hsmd(3750): Client: Received message 10 from client
2019-05-28T22:08:02.528Z lightning_hsmd(3750): Client: Received message 10 from client
2019-05-28T22:08:02.529Z lightning_hsmd(3750): Client: Received message 10 from client
2019-05-28T22:08:03.684Z lightningd(3740): bitcoin-cli estimatesmartfee 2 CONSERVATIVE exited with status 1
2019-05-28T22:08:07.783Z lightningd(3740): Adding block 556142: 000000000000000000173e47871cbacd921ab24034ba9de80e40af84d3d703d5

• nothing happens from here on -
  when stracing it with -f the following output is produced:
  http://drop.geekbox.info/strace.log

[ZmnSCPxj]

The last thing I am seeing on strace is that we are polling on fds 5, 7, 17, 20, and 19.

• 5 = pay plugin. Seems to have gotten its manifest out and is now waiting for commands, so fine.
• 7 = autoclean plugin. Same as above.
• 17 = hsmd.
• 20 = connectd.
• 19 = gossipd.

This poll is thus the main io-loop.

The issue is that topology should be scanning forward for new blocks continuously, but strace shows it has only scanned one block, then after reading it, topology updates the db, but suddenly we enter the main loop (which we should not, because, topology should have its own loop....?).

@cdecker there may be a race condition? The main io_loop blocks on poll, but the topology loop should be running?

[ZmnSCPxj]

I believe I have cracked this issue.

After starting up plugins and the core daemons (hsmd, gossipd, connectd), one of the things we do is setup_topology:

lightning/lightningd/lightningd.c

Lines 744 to 747 in 1141243

	/*~ Initialize block topology. This does its own io_loop to
	* talk to bitcoind, so does its own db transactions. */
	setup_topology(ld->topology, &ld->timers,
	min_blockheight, max_blockheight);

As the comment says, it does an io_loop, which (in the absence of struct timers) will only exit if we execute a io_break.

Looking inside setup_topology, we see that io_loop is called without any struct timers (i.e. the NULL arguments):

lightning/lightningd/chaintopology.c

Lines 896 to 897 in 1141243

	/* Once it gets initial block, it calls io_break() and we return. */
	io_loop(NULL, NULL);

Now, just prior to the above io_loop, we see that we initiate fee estimation:

lightning/lightningd/chaintopology.c

Line 894 in 1141243

start_fee_estimate(topo);

In particular, we only execute io_break if we get our first block and we get our first fee estimation. That's this code below:

lightning/lightningd/chaintopology.c

Lines 29 to 38 in 1141243

	/* get_init_blockhash sets topo->root, start_fee_estimate clears
	* feerate_uninitialized (even if unsuccessful) */
	static void maybe_completed_init(struct chain_topology *topo)
	{
	if (topo->feerate_uninitialized)
	return;
	if (!topo->root)
	return;
	io_break(topo);
	}

And if we look at the logs:

2019-05-28T22:08:03.684Z lightningd(3740): bitcoin-cli estimatesmartfee 2 CONSERVATIVE exited with status 1

Looks like fee estimation from bitcoin-cli exited with status 1.

We search for this text exited with status and see:

lightning/lightningd/bitcoind.c

Lines 157 to 159 in 1141243

	log_unusual(bitcoind->log,
	"%s exited with status %u",
	bcli_args(tmpctx, bcli), exitstatus);

And we scroll down a little and also see that, in case of such a failure, the bitcoind system will helpfully automatically retry the command 1 second later (in particular, it will not invoke the callback inside chaintopology yet):

lightning/lightningd/bitcoind.c

Lines 163 to 165 in 1141243

	/* Retry in 1 second (not a leak!) */
	new_reltimer(&bitcoind->ld->timers, notleak(bcli), time_from_sec(1),
	retry_bcli, bcli);

Of course, it uses a timer..... which the setup_topology loop does not enable. Remember?

lightning/lightningd/chaintopology.c

Lines 896 to 897 in 1141243

	/* Once it gets initial block, it calls io_break() and we return. */
	io_loop(NULL, NULL);

TLDR: If fee estimation completely fails, we retry 1 second later. Unfortunately, the initial setup_topology creates a io_loop that ignores timers. So we never retry fee estimation and just end up hanging.

@cdecker @rustyrussell it seems to me that the simplest solution is to write a io_loop_with_timers that handles timers, and merge the mainloop and the tiny io_loop in setup_topology to io_loop_with_timers. Is this safe? Why does the chaintopology io_loop ignore timers?

[svewa]

https://drop.geekbox.info/feeestimateerror.log

It seems the error was the whole time, that my bitcoind was 17.1 and did not support the 2nd paramter to the getsmartfeeestimate.... your patch made the verbose error message visible, but a check if the available bitcoind has the required features or minimum version would be helpful for sure, too.

[ZmnSCPxj]

@svewa okay, I shall open a separate new issue.