Crash on startup

[sadilek]

Seconds after starting lightningd, it crashes with this output:

lightningd: Fatal signal 11
0x432bcd crashdump
        common/daemon.c:37
0x7f74406a74af ???
        ???:0
0x407a03 get_block_height
        lightningd/chaintopology.c:556
0x409fba peer_start_channeld
        lightningd/channel_control.c:229
0x424e9d peer_connected
        lightningd/peer_control.c:494
0x40bc3c gossip_msg
        lightningd/gossip_control.c:161
0x42cc36 sd_msg_read
        lightningd/subd.c:503
0x42c55d read_fds
        lightningd/subd.c:330
0x465ecf next_plan
        ccan/ccan/io/io.c:59
0x4669a6 do_plan
        ccan/ccan/io/io.c:387
0x4669e4 io_ready
        ccan/ccan/io/io.c:397
0x468550 io_loop
        ccan/ccan/io/poll.c:310
0x40818a setup_topology
        lightningd/chaintopology.c:744
0x4146dc main
        lightningd/lightningd.c:392
0x7f744069282f ???
        ???:0
0x403518 ???
        ???:0
0xffffffffffffffff ???
        ???:0
lightning_channeld: Writing out status 65522: Broken pipe
Segmentation fault (core dumped)

I'm synced to 91d149b.

[sadilek]

I just found out that if I start lightningd with --rescan=1000, it doesn't crash immediately. I wanted to experiment with the value to find the smallest value at which it doesn't crash, and noticed that every time I kill lightningd and restart it, it starts scanning further in the past (if it doesn't crash immediately). It still crashes with small values (50, 100) for --rescan, so the crash, if really related to the rescanning, seems to not be caused by the absolute blockheight but to be related to the relative --rescan value.

[9735dev]

I get something similar, but slightly different. I get the console message from a different child process, but same message: lightning_onchaind: Writing out status 65522: Broken pipe
I've experienced this happening for 2 or 3 starts in a row, and then it works.
Here's the partial log info (build of commit 91d149b):

2018-04-28T10:40:28.151Z lightningd(3686): Forcing fee rate, ignoring estimate
2018-04-28T10:40:28.158Z lightningd(3686): Listening on 'lightning-rpc'
2018-04-28T10:40:28.160Z lightningd(3686): Server started with public key <redacted>, alias <redacted> (color #<redacted>) and lightningd v0.5.2-2016-11-21-2610-g91d149b
2018-04-28T10:40:28.160Z lightningd(3686): /bitcoin-0.16.0/bin/bitcoin-cli -datadir=/bitcoin-unpruned-txindex -rpcuser=<redacted> -rpcpassword=<redacted> sendrawtransaction <redacted> No child processes
2018-04-28T10:40:28.165Z lightningd(3686): FATAL SIGNAL 6
2018-04-28T10:40:28.165Z lightningd(3686): backtrace: common/daemon.c:42 (crashdump) 0x433275
2018-04-28T10:40:28.165Z lightningd(3686): backtrace: (null):0 ((null)) 0x7f24f0d584af
2018-04-28T10:40:28.165Z lightningd(3686): backtrace: (null):0 ((null)) 0x7f24f0d58428
2018-04-28T10:40:28.165Z lightningd(3686): backtrace: (null):0 ((null)) 0x7f24f0d5a029
2018-04-28T10:40:28.165Z lightningd(3686): backtrace: lightningd/log.c:553 (fatal) 0x416331
2018-04-28T10:40:28.165Z lightningd(3686): backtrace: lightningd/bitcoind.c:162 (bcli_finished) 0x403ffd
2018-04-28T10:40:28.165Z lightningd(3686): backtrace: ccan/ccan/io/poll.c:183 (destroy_conn) 0x46bb03
2018-04-28T10:40:28.165Z lightningd(3686): backtrace: ccan/ccan/io/poll.c:189 (destroy_conn_close_fd) 0x46bb23
2018-04-28T10:40:28.165Z lightningd(3686): backtrace: ccan/ccan/tal/tal.c:240 (notify) 0x476409
2018-04-28T10:40:28.165Z lightningd(3686): backtrace: ccan/ccan/tal/tal.c:400 (del_tree) 0x4768ba
2018-04-28T10:40:28.165Z lightningd(3686): backtrace: ccan/ccan/tal/tal.c:511 (tal_free) 0x476cec
2018-04-28T10:40:28.165Z lightningd(3686): backtrace: ccan/ccan/io/io.c:443 (io_close) 0x46a4ee
2018-04-28T10:40:28.165Z lightningd(3686): backtrace: ccan/ccan/io/poll.c:314 (io_loop) 0x46bf12
2018-04-28T10:40:28.165Z lightningd(3686): backtrace: lightningd/lightningd.c:427 (main) 0x41480e
2018-04-28T10:40:28.165Z lightningd(3686): backtrace: (null):0 ((null)) 0x7f24f0d4382f
2018-04-28T10:40:28.165Z lightningd(3686): backtrace: (null):0 ((null)) 0x403518
2018-04-28T10:40:28.165Z lightningd(3686): backtrace: (null):0 ((null)) 0xffffffffffffffff

[cdecker]

The crash-log posted by @sadilek seems to indicate that we are receiving an incoming connection before we have constructed the first in-memory block. We should probably defer spinning up gossipd at all before we have an initial hold on the first block to start from.

The crash from @9735dev seems to be unrelated and is related to some bitcoin-cli process tracking mixup:

lightning/lightningd/bitcoind.c

Lines 160 to 163 in 91d149b

	while ((ret = waitpid(bcli->pid, &status, 0)) < 0 && errno == EINTR);
	if (ret != bcli->pid)
	fatal("%s %s", bcli_args(bcli),
	ret == 0 ? "not exited?" : strerror(errno));

[sadilek]

My last rescan with 200 (which ended up scanning many more blocks than that due to the mentioned "scanning further into the past") was successful, and I was able to kill and restart lightningd without problems without setting --rescan (defaults to 30) afterwards 4 times. Of course, it could be coincidence that I just happen to not hit anymore the race condition @cdecker suspects.

[sadilek]

My node started crashing during startup again. After a few dozen failed restart attempts, I tried starting without internet connection, and that worked.

[sadilek]

Thanks, I can confirm that #1440 fixed this for me. (Two successful restarts in a row.)