Getting ready for wind here, hiccupped PowerWall by accident, server restart, rebuild ...

Ulmo commented 4 years ago

I accidentally restarted my server without meaning to, so I don't have a lot of time for this, otherwise, I'd try to really dive into it and match other problems and edit the sqlite database and stuff. For now, maybe you can let me know if this is something I should manually fix or if it is a bug.

Issue and Steps to Reproduce

I upgraded my lightningd to master, and found out my wallet and database was deleted. Well, I restored it from backup from almost two years ago, and it did great until it did this:

[code]2019-11-25T23:44:35.036Z INFO 022c715b377856f5e176c52dfbe1f19b0283c4a85d563b1f09a9c7d9b6820ec375-chan#8: State changed from CHANNELD_NORMAL to AWAITING_UNILATERAL
2019-11-25T23:44:35.036Z INFO 022c715b377856f5e176c52dfbe1f19b0283c4a85d563b1f09a9c7d9b6820ec375-chan#8: State changed from AWAITING_UNILATERAL to FUNDING_SPEND_SEEN
2019-11-25T23:44:35.037Z DEBUG 022c715b377856f5e176c52dfbe1f19b0283c4a85d563b1f09a9c7d9b6820ec375-onchaind-chan#8: pid 29541, msgfd 41
2019-11-25T23:44:35.039Z DEBUG 02e4f9fbf93b1e82505064c9fe4a51bcadafe0d54645ca5d88ebf97f83d71246ae-chan#119: Got UTXO spend for 9bc178c5a744c1c8d581e46620eaf5d7328e24e80e07bce1db450835dca261f9:0: 862946f5c929194d31e1cbd3bd3a83e185160438f2d29b14d4896c789a21116c
2019-11-25T23:44:35.039Z UNUSUAL 02e4f9fbf93b1e82505064c9fe4a51bcadafe0d54645ca5d88ebf97f83d71246ae-chan#119: Peer permanent failure in CHANNELD_NORMAL: Funding transaction spent
2019-11-25T23:44:35.039Z **BROKEN** 02e4f9fbf93b1e82505064c9fe4a51bcadafe0d54645ca5d88ebf97f83d71246ae-chan#119: Cannot broadcast our commitment tx: it's invalid! (ancient channel?)
2019-11-25T23:44:35.039Z INFO 02e4f9fbf93b1e82505064c9fe4a51bcadafe0d54645ca5d88ebf97f83d71246ae-chan#119: State changed from CHANNELD_NORMAL to AWAITING_UNILATERAL
2019-11-25T23:44:35.059Z **BROKEN** lightningd: FATAL SIGNAL 6 (version v0.7.2.1-747-g17bb862)
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: common/daemon.c:46 (send_backtrace) 0x56205bd77676
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: common/daemon.c:54 (crashdump) 0x56205bd776c1
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x7f6b00230f1f
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x7f6b00230e97
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x7f6b00232800
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x7f6b00222399
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x7f6b00222411
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: bitcoin/tx.c:330 (push_tx) 0x56205bd88660
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: bitcoin/tx.c:354 (linearize_tx) 0x56205bd89330
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: wallet/db.c:1042 (db_bind_tx) 0x56205bd9d0ef
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: wallet/wallet.c:1331 (wallet_channel_save) 0x56205bda2a73
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: lightningd/channel.c:366 (channel_set_state) 0x56205bd4dbb7
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: lightningd/channel.c:396 (channel_fail_permanent) 0x56205bd4ddad
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: lightningd/onchain_control.c:462 (onchaind_funding_spent) 0x56205bd5d62a
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: lightningd/peer_control.c:1068 (funding_spent) 0x56205bd655ca
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: lightningd/watch.c:278 (txowatch_fire) 0x56205bd71fcd
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: lightningd/chaintopology.c:84 (filter_block_txs) 0x56205bd4bc0d
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: lightningd/chaintopology.c:683 (add_tip) 0x56205bd4be4b
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: lightningd/chaintopology.c:758 (have_new_block) 0x56205bd4bef9
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: lightningd/bitcoind.c:478 (process_rawblock) 0x56205bd497b4
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: lightningd/bitcoind.c:225 (bcli_finished) 0x56205bd49518
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: ccan/ccan/io/poll.c:244 (destroy_conn) 0x56205bdb2cc5
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: ccan/ccan/io/poll.c:250 (destroy_conn_close_fd) 0x56205bdb2ce7
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: ccan/ccan/tal/tal.c:235 (notify) 0x56205bdbb532
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: ccan/ccan/tal/tal.c:397 (del_tree) 0x56205bdbb596
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: ccan/ccan/tal/tal.c:481 (tal_free) 0x56205bdbbaf3
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: ccan/ccan/io/io.c:450 (io_close) 0x56205bdb18ef
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: ccan/ccan/io/poll.c:449 (io_loop) 0x56205bdb32af
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: lightningd/io_loop_with_timers.c:24 (io_loop_with_timers) 0x56205bd55ba6
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: lightningd/lightningd.c:848 (main) 0x56205bd59fc1
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x7f6b00213b96
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0x56205bd48679
2019-11-25T23:44:35.059Z **BROKEN** lightningd: backtrace: (null):0 ((null)) 0xffffffffffffffff
log.5448.6 lines 336-378/378 (END)

`getinfo` output

I can't make it stay running, but here's some log header:

2019-11-25T23:44:32.611Z DEBUG lightningd: Opened log file /home/ulmo/logs/log.5448.6
2019-11-25T23:44:32.611Z DEBUG lightningd: Opened log file /home/ulmo/logs/log.5448.6
2019-11-25T23:44:32.613Z DEBUG plugin-manager: started(29403) /usr/local/bin/../libexec/c-lightning/plugins/autoclean
2019-11-25T23:44:32.615Z DEBUG plugin-manager: started(29404) /usr/local/bin/../libexec/c-lightning/plugins/fundchannel
2019-11-25T23:44:32.617Z DEBUG plugin-manager: started(29405) /usr/local/bin/../libexec/c-lightning/plugins/pay
2019-11-25T23:44:32.628Z DEBUG lightningd: testing /usr/local/libexec/c-lightning/lightning_channeld
2019-11-25T23:44:32.631Z DEBUG lightningd: testing /usr/local/libexec/c-lightning/lightning_closingd
2019-11-25T23:44:32.634Z DEBUG lightningd: testing /usr/local/libexec/c-lightning/lightning_connectd
2019-11-25T23:44:32.637Z DEBUG lightningd: testing /usr/local/libexec/c-lightning/lightning_gossipd
2019-11-25T23:44:32.640Z DEBUG lightningd: testing /usr/local/libexec/c-lightning/lightning_hsmd
2019-11-25T23:44:32.644Z DEBUG lightningd: testing /usr/local/libexec/c-lightning/lightning_onchaind
2019-11-25T23:44:32.647Z DEBUG lightningd: testing /usr/local/libexec/c-lightning/lightning_openingd
2019-11-25T23:44:32.670Z DEBUG hsmd: pid 29413, msgfd 23
2019-11-25T23:44:32.684Z DEBUG connectd: pid 29414, msgfd 26
2019-11-25T23:44:32.684Z DEBUG hsmd: Client: Received message 11 from client
2019-11-25T23:44:32.684Z DEBUG hsmd: Client: Received message 9 from client
2019-11-25T23:44:32.684Z DEBUG hsmd: new_client: 0
2019-11-25T23:44:32.698Z DEBUG connectd: Created IPv4 listener on port 9735
2019-11-25T23:44:32.698Z DEBUG connectd: REPLY WIRE_CONNECTCTL_INIT_REPLY with 0 fds
2019-11-25T23:44:32.699Z DEBUG gossipd: pid 29415, msgfd 25
2019-11-25T23:44:32.751Z DEBUG hsmd: Client: Received message 9 from client
2019-11-25T23:44:32.751Z DEBUG hsmd: new_client: 0
2019-11-25T23:44:32.751Z DEBUG gossipd: gossip_store_compact_offline: 0 deleted, 0 copied
2019-11-25T23:44:32.751Z DEBUG gossipd: total store load time: 0 msec
2019-11-25T23:44:32.751Z DEBUG gossipd: gossip_store: Read 0/0/0/0 cannounce/cupdate/nannounce/cdelete from store (0 deleted) in 1 bytes
2019-11-25T23:44:32.751Z DEBUG gossipd: seeker: state = STARTING_UP New seeker
2019-11-25T23:44:32.793Z DEBUG lightningd: Smoothed feerate estimate for urgent initialized to polled estimate 9015
2019-11-25T23:44:32.793Z DEBUG lightningd: Feerate estimate for urgent set to 9015 (was 0)
2019-11-25T23:44:32.793Z DEBUG lightningd: Smoothed feerate estimate for normal initialized to polled estimate 7509
2019-11-25T23:44:32.793Z DEBUG lightningd: Feerate estimate for normal set to 7509 (was 0)
2019-11-25T23:44:32.793Z DEBUG lightningd: Smoothed feerate estimate for slow initialized to polled estimate 250
2019-11-25T23:44:32.793Z DEBUG lightningd: ... feerate estimate for slow hit floor 253
2019-11-25T23:44:32.793Z DEBUG lightningd: Feerate estimate for slow set to 253 (was 0)
2019-11-25T23:44:32.825Z DEBUG lightningd: Adding block 512833: 00000000000000000032aae92f3e9bb07eeb7d0c39986672ed8656dea5a5b625
2019-11-25T23:44:32.833Z DEBUG wallet: Loaded 0 HTLC signatures from DB

Ulmo commented 4 years ago

I deleted that channel, and restarted it. Let's see what happens!

Ulmo commented 4 years ago

Deleting that channel let lightningd complete inputting the rest of the blocks, and now it seems to be running.

It's nice that I was able to upgrade from an old database version today to restore the dragon:

2019-11-25T23:24:04.340Z INFO database: Updating database from version 42 to 115

I just had the above bug, and everything else seemed to work with today's most recent version. I haven't tested it, but it's running. That's one of the smoothest upgrades I've done of lightningd in a while.

cdecker commented 4 years ago

I upgraded my lightningd to master, and found out my wallet and database was deleted. Well, I restored it from backup from almost two years ago, and it did great until it did this:

@rustyrussell could this be related to the recent switch to per-network subdirectories? @Ulmo is there a subdirectory in the lightning-dir called bitcoin? If yes that's where the config, database and hsm_secret files should have been moved.

ElementsProject / lightning