Fatal signal 6 after getblock fails.

[dan-da]

I'm still having trouble getting lightningd to run reliably against spruned. Both operating over tor. Maybe slow tor/network is a root cause, but I don't think lightningd should crash because of it.

What I notice is that:

1. there will be some calls to getblock that fail exiting with status 1. These seems to be handled ok.

2. The crash occurs after a different log message is printed containing the string "(after xx other errors)".

2019-06-29T11:32:16.241Z lightningd(15089): bitcoin-cli -datadir=/home/c-lightning/.bitcoin getblock 000000000000000000153dc4fc7ec2aa952cbcaeecbdb15cf1b5526e1924ca17 false exited with status 1
2019-06-29T11:32:18.330Z lightningd(15089): bitcoin-cli -datadir=/home/c-lightning/.bitcoin getblock 000000000000000000153dc4fc7ec2aa952cbcaeecbdb15cf1b5526e1924ca17 false exited with status 1
2019-06-29T11:32:20.436Z lightningd(15089): bitcoin-cli -datadir=/home/c-lightning/.bitcoin getblock 000000000000000000153dc4fc7ec2aa952cbcaeecbdb15cf1b5526e1924ca17 false exited with status 1
2019-06-29T11:32:22.330Z lightningd(15089): bitcoin-cli -datadir=/home/c-lightning/.bitcoin getblock 000000000000000000153dc4fc7ec2aa952cbcaeecbdb15cf1b5526e1924ca17 false exited 1 (after 16 other errors) 'error code: -1?error message:?Server error?'
2019-06-29T11:32:23.099Z lightningd(15089): FATAL SIGNAL 6 (version v0.7.1rc4)
2019-06-29T11:32:23.099Z lightningd(15089): backtrace: common/daemon.c:45 (send_backtrace) 0x4296b5
2019-06-29T11:32:23.099Z lightningd(15089): backtrace: common/daemon.c:53 (crashdump) 0x4296fb
2019-06-29T11:32:23.099Z lightningd(15089): backtrace: (null):0 ((null)) 0x7f24217fccaf
2019-06-29T11:32:23.099Z lightningd(15089): backtrace: (null):0 ((null)) 0x7f24217fcc37
2019-06-29T11:32:23.099Z lightningd(15089): backtrace: (null):0 ((null)) 0x7f2421800027
2019-06-29T11:32:23.099Z lightningd(15089): backtrace: lightningd/log.c:622 (fatal) 0x413a3e
2019-06-29T11:32:23.099Z lightningd(15089): backtrace: lightningd/bitcoind.c:150 (bcli_failure) 0x4047e0
2019-06-29T11:32:23.099Z lightningd(15089): backtrace: lightningd/bitcoind.c:197 (bcli_finished) 0x4049bf
2019-06-29T11:32:23.099Z lightningd(15089): backtrace: ccan/ccan/io/poll.c:244 (destroy_conn) 0x457ca9
2019-06-29T11:32:23.099Z lightningd(15089): backtrace: ccan/ccan/io/poll.c:250 (destroy_conn_close_fd) 0x457cc2
2019-06-29T11:32:23.099Z lightningd(15089): backtrace: ccan/ccan/tal/tal.c:235 (notify) 0x4600bf
2019-06-29T11:32:23.099Z lightningd(15089): backtrace: ccan/ccan/tal/tal.c:397 (del_tree) 0x46015c
2019-06-29T11:32:23.099Z lightningd(15089): backtrace: ccan/ccan/tal/tal.c:481 (tal_free) 0x460696
2019-06-29T11:32:23.099Z lightningd(15089): backtrace: ccan/ccan/io/io.c:450 (io_close) 0x456a7b
2019-06-29T11:32:23.099Z lightningd(15089): backtrace: ccan/ccan/io/poll.c:449 (io_loop) 0x4581f9
2019-06-29T11:32:23.099Z lightningd(15089): backtrace: lightningd/io_loop_with_timers.c:24 (io_loop_with_timers) 0x40e7f3
2019-06-29T11:32:23.099Z lightningd(15089): backtrace: lightningd/lightningd.c:827 (main) 0x412285
2019-06-29T11:32:23.099Z lightningd(15089): backtrace: (null):0 ((null)) 0x7f24217e7f44
2019-06-29T11:32:23.099Z lightningd(15089): backtrace: (null):0 ((null)) 0x403d2d
2019-06-29T11:32:23.099Z lightningd(15089): backtrace: (null):0 ((null)) 0xffffffffffffffff

[ZmnSCPxj]

This means that we have been retrying and retrying the command for one minute already.

lightning/lightningd/bitcoind.c

Lines 148 to 155 in fc6de94

	t = timemono_between(time_mono(), bitcoind->first_error_time);
	if (time_greater(t, time_from_sec(60)))
	fatal("%s exited %u (after %u other errors) '%.*s'",
	bcli_args(tmpctx, bcli),
	exitstatus,
	bitcoind->error_count,
	(int)bcli->output_bytes,
	bcli->output);

The assumption is that the bitcoind connection is broken, so we should signal the operator (you) that you should check your setup. We do this by the fatal crash.

So possibly there is a problem with spruned. You could check this: #855 (comment)

[dan-da]

thanks for the clarification. However, I think this needs to be fine tuned a bit.

First off, when I run a daemon on a server, I expect it to just keep running unless something really fatal happens like running out of disk/mem or a serious bug is encountered. bitcoind does this, and I have an expectation that lightningd, as a financial agent, will be just as bulletproof.

Second, I am running spruned over tor, which means it sometimes has lags, etc. Also, my router resets every day which may take a minute or more. As such, this 1 minute limit seems way too restrictive. I would like a config option to increase or disable it.

Third, the log message did not indicate that the command had been retried for a minute and that exceeding this limit is a fatal error condition. So even after getting my attention, I believed it to be a bug in lightningd, that it cannot properly handle the case when getblock fails.

Fourth, if it really is necessary to disable lightningd operations (more justification needed?), then I would suggest creating some sort of "operations suspended" mode. So the RPC server would still be alive and can be queried for current status. Thus, the operator can easily run a script that will monitor the status via rpc and alert (email, sms or whatever) or take other corrective action in case of such an error condition. Further, once the situation is resolved, it should be possible to signal lightningd to resume operations and/or it should periodically retry.

note: yes I am aware that lightningd can be run in a shell script that can restart, alert, etc. Actually, I have this going. But I view it as a workaround because spruned+lightningd are unstable in my env. I am filing these reports in the hopes that it becomes rock solid and this pain point goes away.

[ZmnSCPxj]

if it really is necessary to disable lightningd operations (more justification needed?)

It is really needed for the operator to panic in this case. Without a bitcoind, the lightningd cannot know if existing channels are being cheated by counterparties, leading to financial loss and threatening the rest of the network (which has a sort of "herd immunity"; as long as most people have lightning nodes that cannot be stolen from, the few who cannot have reliable lightning nodes are largely protected as there is no incentive to attempt cheats in practice). I am uncertain if an "operations suspended" mode is enough to make the operator panic; perhaps a "LIGHTNING NODE BROKEN YOU MAY LOSE FUNDS" mode fits this more clearly.

[dan-da]

my funds are fatally at risk after one minute of lost connectivity?!!!

that seems to be overstating the case to me. if not, please provide examples where this is necessary after just 60 seconds else funds will be lost. Because if that's really the case, I don't see how I can ever place much trust in lightning network...

Anyway, I urge maintainers to re-think this decision. Practically, it just results in an unstable system, at least for me.

In my particular use case, I do not even have funds at risk.... 0 channels. I merely (attempt) to run a node to monitor stats about the network. Yet lightningd is "protecting" me by segfaulting regularly. And then it sometimes takes ages to start up again due to #2778. The result is an unstable system that is presently not meeting my goals for it.

Yes, I realize the above is because I'm trying to run both spruned and lightningd over tor, and because my router resets once a day. But these are not especially uncommon things. I think the system should be resilient enough to handle them, or at least allow me to tune it (via a timeout setting). Indeed, I will not be running it in real-world use or recommending to other until it can reliably operate in my environment.

further, it is certainly possible for the server to detect that I do NOT have funds at risk since the last 60 seconds, so it doesn't need to do something fatal or enter a special mode.

[NicolasDorier]

@ZmnSCPxj I think it is good that it crash in this situation. A better error message would go a long way though.

LND, same situation, get in a unrecoverable zombie state, neither alive nor completely dead, meaning the operator can't even panic or restart the process. -_-

[ZmnSCPxj]

@dan-da @NicolasDorier see #2780 . Failure is related to #2782 , which will be fixed by #2783 , so once #2783 is merged in, I will rebase.

[dan-da]

@ZmnSCPxj thx, this looks good. I'll test it out once merged.

[darosior]

@dan-da how did the test go ?

[dan-da]

@darosior thx for reminding me. I'm compiling latest code now and will give it a try assuming build is successful.

[dan-da]

hmm, I get an error message that seems to indicate lightningd is incompatible with spruned 0.0.10 I have running. spruned latest commit is May 17, so I have latest code.

Here's the error message printed from lightningd, which seems to be returned from spruned.

$ lightningd 
Invalid 'initialblockdownload' field in getblockchaininfo '{
  "chain": "main",
  "warning": "spruned 0.0.10, emulating bitcoind v0.16",
  "blocks": 598500,
  "headers": 598500,
  "bestblockhash": "00000000000000000002957e1186941dffe9f1c9460c7e93351040aefca8800b",
  "difficulty": 0,
  "chainwork": "0000000000000000000000000000000000000000000000000000000000000000",
  "mediantime": 1570562099,
  "verificationprogress": 0,
  "pruned": false
}

I guess that should be opened as a separate issue, assuming spruned compatibility is still a goal. and/or it could/should be fixed on spruned side, but maybe the project is not active...

[niftynei]

@dan-da has this issue been resolved?

[dan-da]

seemingly not resolved. I applied the spruned patch a few weeks ago and since then lightningd has been able to run but I see it is still being restarted quite often by my monitoring script, eg:

Wed Oct 23 09:10:07 PDT 2019 - lightningd not running.  Starting
Wed Oct 23 09:13:49 PDT 2019 - lightningd not running.  Starting
Wed Oct 23 09:17:47 PDT 2019 - lightningd not running.  Starting
Wed Oct 23 09:21:30 PDT 2019 - lightningd not running.  Starting
Wed Oct 23 09:25:27 PDT 2019 - lightningd not running.  Starting
Wed Oct 23 09:29:10 PDT 2019 - lightningd not running.  Starting
Wed Oct 23 09:31:58 PDT 2019 - lightningd not running.  Starting

number of restarts per day:

$ tail -n 200 /tmp/lightningd-monitor.log | grep "Oct 23" | wc -l
137
$ tail -n 200 /tmp/lightningd-monitor.log | grep "Oct 22" | wc -l
7
$ tail -n 200 /tmp/lightningd-monitor.log | grep "Oct 21" | wc -l
0
$ tail -n 200 /tmp/lightningd-monitor.log | grep "Oct 20" | wc -l
0
$ tail -n 200 /tmp/lightningd-monitor.log | grep "Oct 19" | wc -l
1
$ tail -n 200 /tmp/lightningd-monitor.log | grep "Oct 18" | wc -l
4
$ tail -n 200 /tmp/lightningd-monitor.log | grep "Oct 17" | wc -l
12
$ tail -n 200 /tmp/lightningd-monitor.log | grep "Oct 16" | wc -l
0

in .lightning/debug.log, it looks like this before a restart:

2019-08-26T07:38:41.264Z lightningd(7780): bitcoin-cli -datadir=/home/c-lightning/.bitcoin getblock 0000000000000000000fd0cd002a8aa06c9
313d2b847377bd90a90287e229040 false exited with status 1
2019-08-26T07:38:49.698Z lightningd(7780): --------------------------------------------------
2019-08-26T07:38:49.698Z lightningd(7780): Server started with public key <key>
4f9ba, alias <alias> (color #000000) and lightningd v0.7.1rc4

lightningd was built from Oct 8 commit f019dc3

[dan-da]

oh, woops I forgot there is a timeout setting now. I will set it longer and see.