Peer permanent failure in ONCHAIND_THEIR_UNILATERAL

[toshinoriK]

Node crashes during startup after scanning block 506935 and attempting to resolve a peer permanent failure ONCHAIND_THEIR_UNILATERAL.

The node crashed on the 31st, possibly around the time of block 506935, but I do not have a log for this crash.

Log and backtrace:

lightningd(4288): Adding block 506935: 0000000000000000000cc6ac7057ed757281ed9301c8ad6a4d8a4a30d9059de6
lightningd(4288): peer {__PEER_ID__}: Got UTXO spend for {__TX_ID_1__}:0: {__TX_ID_2__}
lightningd(4288): peer {__PEER_ID__}: Peer permanent failure in ONCHAIND_THEIR_UNILATERAL: Funding transaction spent
lightningd(4288):        (tx {__TX_ID_3__})
lightningd(4288): sendrawtransaction: {__TX_HASH_1__}
lightningd(4288): peer {__PEER_ID__}: State changed from ONCHAIND_THEIR_UNILATERAL to FUNDING_SPEND_SEEN
lightningd(4288): lightning_onchaind({__PEER_ID__}): pid 12097, msgfd 16
lightningd(4288): peer {__PEER_ID__}: We want to know if htlc 0 is missing (immediate)
lightningd(4288): sendrawtx exit 25, gave error code: -25
error message:
Missing inputs

lightning_gossipd(4296): TRACE: req: type WIRE_GOSSIP_DISABLE_CHANNEL len 12
lightning_gossipd(4296): TRACE: Unable to find channel {__CHANNEL_ID__}
lightningd(4288): lightning_onchaind({__PEER_ID__}): TRACE: Tracking output 0 of {__TX_ID_1__}: FUNDING_TRANSACTION/FUNDING_OUTPUT
lightningd(4288): lightning_onchaind({__PEER_ID__}): TRACE: Remote per-commit point: {__REMOTE_PER_COMMIT_POINT__}
lightningd(4288): lightning_onchaind({__PEER_ID__}): TRACE: Old remote per-commit point: {__OLD_REMOTE_PER_COMMIT_POINT__}
lightningd(4288): lightning_onchaind({__PEER_ID__}): TRACE: commitnum = 561, revocations_received = 561
lightningd(4288): lightning_onchaind({__PEER_ID__}): TRACE: Their unilateral tx, old commit point
lightningd(4288): lightning_onchaind({__PEER_ID__}): UPDATE WIRE_ONCHAIN_INIT_REPLY
lightningd(4288): peer {__PEER_ID__}: State changed from FUNDING_SPEND_SEEN to ONCHAIND_THEIR_UNILATERAL
lightningd(4288): lightning_onchaind({__PEER_ID__}): TRACE: Initial feerate 0 to 42606
lightningd(4288): lightning_onchaind({__PEER_ID__}): TRACE: Resolved FUNDING_TRANSACTION/FUNDING_OUTPUT by THEIR_UNILATERAL ({__TX_ID_2__})
lightningd(4288): lightning_onchaind({__PEER_ID__}): TRACE: Deriving keyset 561: per_commit_point={__OL_REMOTE_PER_COMMIT_POINT__} self_payment_basepoint={__SELF_PAYMENT_BASEPOINT__} other_payment_basepoint={__OTHER_PAYMENT_BASEPOINT__} self_htlc_basepoint={__SELF_HTLC_BASEPOINT__} other_htlc_basepoint={__OTHER_HTLC_BASEPOINT__} self_delayed_basepoint={__SELF_DELAYED_BASEPOINT__} other_revocation_basepoint={__OTHER_REVOCATION_BASEPOINT__}
lightningd(4288): lightning_onchaind({__PEER_ID__}): TRACE: Deconstructing unilateral tx: 561 using keyset:  self_revocation_key: {__SELF_REVOCATION_KEY__} self_delayed_payment_key: {__SELF_DELAYED_PAYMENT_KEY} self_payment_key: {__SELF_PAYMENT_KEY__} other_payment_key: {__other_payment_key__} self_htlc_key: {__SELF_HTLC_KEY__} other_htlc_key: {__OTHER_HTLC_KEY__}
lightningd(4288): lightning_onchaind({__PEER_ID__}): TRACE: Script to-them: 144: {__SCRIPT_TO_THEM__} (6321{__SELF_REVOCATION_KEY__}67029000b27521{__SELF_DELAYED_PAYMENT_KEY}68ac)
lightningd(4288): lightning_onchaind({__PEER_ID__}): TRACE: Script to-me: {__SCRIPT_TO_ME__}
lightningd(4288): lightning_onchaind({__PEER_ID__}): TRACE: Output 0: {__SCRIPT_TO_ME__}
lightningd(4288): lightning_onchaind({__PEER_ID__}): TRACE: Tracking output 0 of {__TX_ID_2__}: THEIR_UNILATERAL/OUTPUT_TO_US
lightningd(4288): lightning_onchaind({__PEER_ID__}): TRACE: Ignoring output 0 of {__TX_ID_2__}: THEIR_UNILATERAL/OUTPUT_TO_US
lightningd(4288): lightning_onchaind({__PEER_ID__}): UPDATE WIRE_ONCHAIN_ADD_UTXO
lightningd(4288): lightning_onchaind({__PEER_ID__}): UPDATE WIRE_ONCHAIN_MISSING_HTLC_OUTPUT
lightningd(4288): FATAL SIGNAL 11 RECEIVED
lightningd(4288): backtrace: lightningd/log.c:437 (log_crash) 0x410646
lightningd(4288): backtrace: (null):0 ((null)) 0x7ffb85be926f
lightningd(4288): backtrace: lightningd/pay.c:115 (local_routing_failure) 0x4141e7
lightningd(4288): backtrace: lightningd/pay.c:221 (payment_failed) 0x414505
lightningd(4288): backtrace: lightningd/peer_htlcs.c:785 (onchain_failed_our_htlc) 0x420872
lightningd(4288): backtrace: lightningd/peer_control.c:1241 (handle_missing_htlc_output) 0x4195fe
lightningd(4288): backtrace: lightningd/peer_control.c:1355 (onchain_msg) 0x419a38
lightningd(4288): backtrace: lightningd/subd.c:477 (sd_msg_read) 0x423c45
lightningd(4288): backtrace: ccan/ccan/io/io.c:59 (next_plan) 0x459488
lightningd(4288): backtrace: ccan/ccan/io/io.c:387 (do_plan) 0x459f5a
lightningd(4288): backtrace: ccan/ccan/io/io.c:397 (io_ready) 0x459f98
lightningd(4288): backtrace: ccan/ccan/io/poll.c:305 (io_loop) 0x45b840
lightningd(4288): backtrace: lightningd/lightningd.c:347 (main) 0x40f0a4
lightningd(4288): backtrace: (null):0 ((null)) 0x7ffb85bd5c04
lightningd(4288): backtrace: (null):0 ((null)) 0x403184
lightningd(4288): backtrace: (null):0 ((null)) 0xffffffffffffffff
Fatal signal 11. 0x41072c log_crash
        lightningd/log.c:463
0x7ffb85be926f ???
        ???:0
0x4141e7 local_routing_failure
        lightningd/pay.c:115
0x414505 payment_failed
        lightningd/pay.c:221
0x420872 onchain_failed_our_htlc
        lightningd/peer_htlcs.c:785
0x4195fe handle_missing_htlc_output
        lightningd/peer_control.c:1241
0x419a38 onchain_msg
        lightningd/peer_control.c:1355
0x423c45 sd_msg_read
        lightningd/subd.c:477
0x459488 next_plan
        ccan/ccan/io/io.c:59
0x459f5a do_plan
        ccan/ccan/io/io.c:387
0x459f98 io_ready
        ccan/ccan/io/io.c:397
0x45b840 io_loop
        ccan/ccan/io/poll.c:305
0x40f0a4 main
        lightningd/lightningd.c:347
0x7ffb85bd5c04 ???
        ???:0
0x403184 ???
        ???:0
0xffffffffffffffff ???
        ???:0
Log dumped in crash.log
Segmentation fault

[ZmnSCPxj]

Looking at it, it seems the crash is caused because, there is no struct wallet_payment corresponding to the hash, with local_routing_faillure attempting to access this structure. local_routing_failure wants to do this so it can know the first channel that is failing, to report to gossipd.

In this case, maybe we can simply punt and not report to the gossipd, lacking information, and just print an "unusual" message.

[toshinoriK]

Here is some additional debug info from gdb

Program received signal SIGSEGV, Segmentation fault.
0x00000000004155bd in local_routing_failure (ctx=0x2ea7280, ld=0x6dd140, hout=0x827f10, payment=0x0) at lightningd/pay.c:180
180             routing_failure->erring_channel = payment->route_channels[0];
(gdb) bt
#0  0x00000000004155bd in local_routing_failure (ctx=0x2ea7280, ld=0x6dd140, hout=0x827f10, payment=0x0) at lightningd/pay.c:180
#1  0x00000000004159be in payment_failed (ld=0x6dd140, hout=0x827f10, 
    localfail=0x31ddd10 "WIRE_PERMANENT_CHANNEL_FAILURE: missing in commitment tx") at lightningd/pay.c:299
#2  0x0000000000421d18 in onchain_failed_our_htlc (peer=0x814950, htlc=0x7fffffffdb10, why=0x4a00f2 "missing in commitment tx")
    at lightningd/peer_htlcs.c:783
#3  0x000000000041aa71 in handle_missing_htlc_output (peer=0x814950, msg=0x1ebb150 "\023\221") at lightningd/peer_control.c:1241
#4  0x000000000041aeab in onchain_msg (sd=0x2da2c60, msg=0x1ebb150 "\023\221", fds=0x0) at lightningd/peer_control.c:1355
#5  0x00000000004250eb in sd_msg_read (conn=0x2da2e70, sd=0x2da2c60) at lightningd/subd.c:477
#6  0x000000000045ada1 in next_plan (conn=0x2da2e70, plan=0x2da2ea0) at ccan/ccan/io/io.c:59
#7  0x000000000045b873 in do_plan (conn=0x2da2e70, plan=0x2da2ea0, idle_on_epipe=false) at ccan/ccan/io/io.c:387
#8  0x000000000045b8b1 in io_ready (conn=0x2da2e70, pollflags=1) at ccan/ccan/io/io.c:397
#9  0x000000000045d159 in io_loop (timers=0x6dd228, expired=0x7fffffffdd38) at ccan/ccan/io/poll.c:305
#10 0x000000000040f732 in main (argc=4, argv=0x7fffffffde68) at lightningd/lightningd.c:351

@ZmnSCPxj So yes, seems when the node crashed the first time, it failed to store (if it existed) the payment in the database and now at startup there is nothing to handle the missing payment.

Also, is my thinking correct that this is no so much an onchaind issue but more so a wallet issue, and then perhaps the title of this issue is not accurate?

[ZmnSCPxj]

More of the payment system. I wonder why it did not store the payment in the first place, however...

Can you command the below to gdb?

display payment
display *payment

[toshinoriK]

(gdb) display payment
1: payment = (const struct wallet_payment *) 0x0
(gdb) display *payment
2: *payment = <error: Cannot access memory at address 0x0>

here is also output of the struct htlc_out hout (w/ details removed)

(gdb) display hout
3: hout = (const struct htlc_out *) 0x827f10
(gdb) display *hout
4: *hout = {dbid = 10, origin_htlc_id = 9, key = {peer = 0x814950, id = 0}, msatoshi = ..., cltv_expiry = 507120, payment_hash = {
    u = {u32 = {2149182001, ...}, 
      u8 = "1\352\031\..."}}, 
  hstate = SENT_ADD_ACK_REVOCATION, 
  onion_routing_packet = "\000\003..."..., failcode = WIRE_PERMANENT_CHANNEL_FAILURE, 
  failuremsg = 0x0, preimage = 0x0, in = 0x0}

[ZmnSCPxj]

Thanks, it really does look like payment was not persisted....

Unfortunately payment persistence is a little beyond my knowledge for now... @rustyrussell help please

[ZmnSCPxj]

@toshinoriK, quick question: what commit hash were you on when you made the payment? Also, if different, what commit hash were you on when you restarted and encountered the crash?

[toshinoriK]

@ZmnSCPxj I will need to dig through the database to get some better idea but I can for sure say that I was on b13c65dacb55e79e1148493fa6c794af678c8660 when I first setup the node and made some successful payments. A few days later I moved to a different machine and compiled from master again, so this is the hash I need to track down as I was on this commit at the time the issue occurred. (Unfortunately I do not have the first crash log)

[ZmnSCPxj]

The quoted commit is before a change in the HTLC and in particular payment persistence (#606).

#606 itself refers to an earlier #588. The comment here is interesting: #588 (comment)

But we don't store 'pay_command' in the database, so we can't restore them!

The current struct wallet_payment is effectively a merge of the old wallet_payment and the old pay_command, I think. As #588 alludes, at that time they were not getting persisted to the database.

I think what happened is this:

1. You used the old b13c65d commit and initiated (but did not yet complete) the payment.
2. You stopped the lightningd while the payment was in-flight.
3. At that time, payments were not correctly being persisted, because that was the bug fixed by Payment persistence #606 and brought up by Fix unitialized fields in htlc_out constructed from wallet database entry #588.
4. You upgraded. The upgrade includes Payment persistence #606, but the database is already inconsistent as the payment was not saved in the first place, only the out-going HTLC (which refers to a payment that does not exist as it was not saved).
5. The upgrade also includes pay hands back failures to gossipd #638, which really does not work without the payment, since any failures need to be propagated to gossipd (so gossipd can update its routemap) and it assumes that payments are properly persisted (because that is what Payment persistence #606 fixed, and Payment persistence #606 was merged before pay hands back failures to gossipd #638). While it is true the routemap probably at this point no longer contains the failing channel (possibly it has been closed long ago) pay hands back failures to gossipd #638 does not check that.
6. There is no wallet_payment matching the out-going HTLC, and so, it is NULL and local_routing_failure cannot determine the first hop.

In principle it should be possible to modify local_routing_failure to get the channel from the out-going HTLC directly. The problem is that the channel is encrypted inside onion_routing_packet, and we would have to decrypt it (indeed, it is the reason why the payment stores the channels along the route --- it stores it in the clear for easy access).

I am inclined to suspect that this bug will occur only in this specific case of upgrading from a pre-#606 to a post-#606 commit, with a payment in-flight. @rustyrussell agree?

[sorce]

I have a node that is currently crashing with the same thing:

2018-02-06T17:23:04.744Z lightningd(12081): Adding block 506444: 000000000000000000336e3c3120dbb93deaad11abd63b9237e0407ae4b1a9f8
2018-02-06T17:23:04.807Z lightningd(12081): peer 02c0ac82c33971de096d87ce5ed9b022c2de678f08002dc37fdb1b6886d12234b5: Got UTXO spend for 5261afd8b75a1d815dd582e7f11e0814edf83fb0d8d12c509a73d40b3338a5d5:1: d1cb3501cc198f77c2dfa66780183f51b26b6f7b1bde414c2cf02f201ce293cb
2018-02-06T17:23:04.807Z lightningd(12081): peer 02c0ac82c33971de096d87ce5ed9b022c2de678f08002dc37fdb1b6886d12234b5: Peer permanent failure in ONCHAIND_THEIR_UNILATERAL: Funding transaction spent
2018-02-06T17:23:04.807Z lightningd(12081): 	 (tx 3a6dfd564affd82111718ed81e9c82d380232ef8dedd23472b7cd94e47ecc294)
2018-02-06T17:23:04.807Z lightningd(12081): sendrawtransaction: 02000000000101d5a538330bd4739a502cd1d8b03ff8ed14081ef1e782d55d811d5ab7d8af6152010000000035b3128001ea090000000000002200209a95f9e125a0f972078c5d44697f30bdb81f0626344f0f3ef5dcfbc62b889b160400483045022100aaa378de4a8fa97b94aadb856f2831bd884540e3de194260b86e35ea17a63a0702200e13bf5c604ee94bec068fab22afa994d97356f145031333a5ac650a1b6c920801483045022100d777cb822f3edce838d4a786df8451a5711669e7a515087bb1cb7ceb287b1961022078be2f8c1c0a1056fbf6f25e2aa0918e6c7e802413334702128943037912fb560147522102fc3da0f6f945e8639c471db2d1312d3d3cb2df254b193162333a51b0114fe86e2103627c640620c204ac0a98ce35723ba5352e5f0bd7e3a69640b9e6be0681d81bfa52aeca3bb120
2018-02-06T17:23:04.811Z lightningd(12081): peer 02c0ac82c33971de096d87ce5ed9b022c2de678f08002dc37fdb1b6886d12234b5: State changed from ONCHAIND_THEIR_UNILATERAL to FUNDING_SPEND_SEEN
2018-02-06T17:23:04.813Z lightningd(12081): lightning_onchaind(02c0ac82c33971de096d87ce5ed9b022c2de678f08002dc37fdb1b6886d12234b5): pid 17583, msgfd 26
2018-02-06T17:23:04.814Z lightningd(12081): peer 02c0ac82c33971de096d87ce5ed9b022c2de678f08002dc37fdb1b6886d12234b5: We want to know if htlc 0 is missing (immediate)
2018-02-06T17:23:04.986Z lightningd(12081): sendrawtx exit 25, gave error code: -25
error message:
Missing inputs

2018-02-06T17:23:04.991Z lightning_gossipd(12111): TRACE: req: type WIRE_GOSSIP_DISABLE_CHANNEL len 12
2018-02-06T17:23:04.991Z lightning_gossipd(12111): TRACE: Unable to find channel 506438:720:1/0
2018-02-06T17:23:04.992Z lightningd(12081): lightning_onchaind(02c0ac82c33971de096d87ce5ed9b022c2de678f08002dc37fdb1b6886d12234b5): TRACE: Tracking output 1 of 5261afd8b75a1d815dd582e7f11e0814edf83fb0d8d12c509a73d40b3338a5d5: FUNDING_TRANSACTION/FUNDING_OUTPUT
2018-02-06T17:23:04.992Z lightningd(12081): lightning_onchaind(02c0ac82c33971de096d87ce5ed9b022c2de678f08002dc37fdb1b6886d12234b5): TRACE: Remote per-commit point: 0203cd6cd173839fb8f99c714c13d0cf7bbe3c51394916aec2d28bc11a843b0bf2
2018-02-06T17:23:04.992Z lightningd(12081): lightning_onchaind(02c0ac82c33971de096d87ce5ed9b022c2de678f08002dc37fdb1b6886d12234b5): TRACE: Old remote per-commit point: 020aa1a893c4cc8c291bbab0af4b605a622a3d9bc6f4cf141c5823bde817ba307b
2018-02-06T17:23:04.992Z lightningd(12081): lightning_onchaind(02c0ac82c33971de096d87ce5ed9b022c2de678f08002dc37fdb1b6886d12234b5): TRACE: commitnum = 3, revocations_received = 3
2018-02-06T17:23:04.992Z lightningd(12081): lightning_onchaind(02c0ac82c33971de096d87ce5ed9b022c2de678f08002dc37fdb1b6886d12234b5): TRACE: Their unilateral tx, old commit point
2018-02-06T17:23:04.992Z lightningd(12081): lightning_onchaind(02c0ac82c33971de096d87ce5ed9b022c2de678f08002dc37fdb1b6886d12234b5): UPDATE WIRE_ONCHAIN_INIT_REPLY
2018-02-06T17:23:04.992Z lightningd(12081): peer 02c0ac82c33971de096d87ce5ed9b022c2de678f08002dc37fdb1b6886d12234b5: State changed from FUNDING_SPEND_SEEN to ONCHAIND_THEIR_UNILATERAL
2018-02-06T17:23:04.994Z lightningd(12081): lightning_onchaind(02c0ac82c33971de096d87ce5ed9b022c2de678f08002dc37fdb1b6886d12234b5): TRACE: Initial feerate 0 to 32404
2018-02-06T17:23:04.994Z lightningd(12081): lightning_onchaind(02c0ac82c33971de096d87ce5ed9b022c2de678f08002dc37fdb1b6886d12234b5): TRACE: Resolved FUNDING_TRANSACTION/FUNDING_OUTPUT by THEIR_UNILATERAL (d1cb3501cc198f77c2dfa66780183f51b26b6f7b1bde414c2cf02f201ce293cb)

...

2018-02-06T17:23:04.994Z lightningd(12081): lightning_onchaind(02c0ac82c33971de096d87ce5ed9b022c2de678f08002dc37fdb1b6886d12234b5): TRACE: Script to-them: 144: 0020c1ca30c6f3ef91255ebd11c26780c4665213b3731f46cb9754698025ab43f08b (632102d1f1ad51112b0149b344719491528cc7b7b929f9d9ad53e882c1ff5297e157c467029000b27521020895dbba06512b6f5af803946db04e9f92383323cb1ffa8c6a0487fb84b9bfc268ac)
2018-02-06T17:23:04.994Z lightningd(12081): lightning_onchaind(02c0ac82c33971de096d87ce5ed9b022c2de678f08002dc37fdb1b6886d12234b5): TRACE: Script to-me: 0014009c7bcbeca5141fd6c72811acd42ab65bfeea53
2018-02-06T17:23:04.995Z lightningd(12081): lightning_onchaind(02c0ac82c33971de096d87ce5ed9b022c2de678f08002dc37fdb1b6886d12234b5): TRACE: Output 0: 0014009c7bcbeca5141fd6c72811acd42ab65bfeea53
2018-02-06T17:23:04.995Z lightningd(12081): lightning_onchaind(02c0ac82c33971de096d87ce5ed9b022c2de678f08002dc37fdb1b6886d12234b5): TRACE: Tracking output 0 of d1cb3501cc198f77c2dfa66780183f51b26b6f7b1bde414c2cf02f201ce293cb: THEIR_UNILATERAL/OUTPUT_TO_US
2018-02-06T17:23:04.995Z lightningd(12081): lightning_onchaind(02c0ac82c33971de096d87ce5ed9b022c2de678f08002dc37fdb1b6886d12234b5): TRACE: Ignoring output 0 of d1cb3501cc198f77c2dfa66780183f51b26b6f7b1bde414c2cf02f201ce293cb: THEIR_UNILATERAL/OUTPUT_TO_US
2018-02-06T17:23:04.995Z lightningd(12081): lightning_onchaind(02c0ac82c33971de096d87ce5ed9b022c2de678f08002dc37fdb1b6886d12234b5): UPDATE WIRE_ONCHAIN_ADD_UTXO
2018-02-06T17:23:04.995Z lightningd(12081): lightning_onchaind(02c0ac82c33971de096d87ce5ed9b022c2de678f08002dc37fdb1b6886d12234b5): UPDATE WIRE_ONCHAIN_MISSING_HTLC_OUTPUT
2018-02-06T17:23:04.995Z lightningd(12081): FATAL SIGNAL 11 RECEIVED
2018-02-06T17:23:05.029Z lightningd(12081): backtrace: lightningd/log.c:473 (log_crash) 0x410ff8
2018-02-06T17:23:05.029Z lightningd(12081): backtrace: (null):0 ((null)) 0x7fb7d2ed44af
2018-02-06T17:23:05.029Z lightningd(12081): backtrace: lightningd/pay.c:231 (local_routing_failure) 0x415a00
2018-02-06T17:23:05.029Z lightningd(12081): backtrace: lightningd/pay.c:355 (payment_failed) 0x415dee
2018-02-06T17:23:05.030Z lightningd(12081): backtrace: lightningd/peer_htlcs.c:783 (onchain_failed_our_htlc) 0x421fda
2018-02-06T17:23:05.031Z lightningd(12081): backtrace: lightningd/peer_control.c:1241 (handle_missing_htlc_output) 0x41aed3
2018-02-06T17:23:05.031Z lightningd(12081): backtrace: lightningd/peer_control.c:1355 (onchain_msg) 0x41b315
2018-02-06T17:23:05.031Z lightningd(12081): backtrace: lightningd/subd.c:477 (sd_msg_read) 0x4253fd
2018-02-06T17:23:05.031Z lightningd(12081): backtrace: ccan/ccan/io/io.c:59 (next_plan) 0x45b39b
2018-02-06T17:23:05.031Z lightningd(12081): backtrace: ccan/ccan/io/io.c:387 (do_plan) 0x45be72
2018-02-06T17:23:05.031Z lightningd(12081): backtrace: ccan/ccan/io/io.c:397 (io_ready) 0x45beb0
2018-02-06T17:23:05.031Z lightningd(12081): backtrace: ccan/ccan/io/poll.c:305 (io_loop) 0x45d76e
2018-02-06T17:23:05.031Z lightningd(12081): backtrace: lightningd/lightningd.c:351 (main) 0x40f842
2018-02-06T17:23:05.032Z lightningd(12081): backtrace: (null):0 ((null)) 0x7fb7d2ebf82f
2018-02-06T17:23:05.032Z lightningd(12081): backtrace: (null):0 ((null)) 0x403248
2018-02-06T17:23:05.032Z lightningd(12081): backtrace: (null):0 ((null)) 0xffffffffffffffff

I checked on the client and realized it had crashed. I had not updated it for a decent period of time (most likely pre-#606, but I am not completely sure of what commit I was running under), so it had just been sitting there. I did a fresh pull to the current master and it is still crashing with the same thing. I unfortunately don't have any other useful information about it.

[toshinoriK]

The last two payments in the database have a timestamp of 2018-01-25 and a status of PAYMENT_COMPLETED, both of which were made after upgrading from b13c65d (not sure which commit, but it was likely on 2018-01-24). The two previous payments were made on the b13c65d commit and also have a status of PAYMENT_COMPLETED.

On the day I noticed the node had crashed (31st), I had not made any payments since the two on the 25th.

[ZmnSCPxj]

@toshinoriK Hmm, I am uncertain then what happened, as your explanation seems to imply that the node was running continuously and only now crashed. Perhaps some payment at b13c65d was created, not stored, then on its way to the destination, another node crashed after it could forward an HTLC but before the preimage was provided, forcing things to get settled on the blockchain, where resolution is slower and there are delays, leading to the delay before the node crashed. In the meantime you must have shut down your own node in order to upgrade it, and the shutdown lost the payment structure that was not getting persisted properly back then. But I am guessing at this point... we could have an actual payment-not-being-persisted bug here.

[rustyrussell]

That's actually unlikely: this change was added in December.

Any chance you can send me your `~/.lightning/lightningd.sqlite3` db?  You can gpg to my 15EE8D6CAB0E7F0CF999BFCBD9200E6CD1ADB8F1 key if you want; rusty@rustcorp.com.au.

(Note: sending me the db is a privacy leak, not a key leak!)

[toshinoriK]

@rustyrussell Sent