search

lightningnetwork / lnd

Lightning Network Daemon ⚡️
MIT License
7.73k stars 2.09k forks source link

lnd crash: panic: runtime error: invalid memory address or nil pointer dereference #528

Closed whizz closed 6 years ago

whizz commented 6 years ago

lnd crashed with "panic: runtime error: invalid memory address or nil pointer dereference".

Running on CentOS 7 Linux go version go1.9.2 linux/amd64

Here are the last 100 or so lines from log:

2017-12-27 13:53:49.585 [INF] CRTR: New channel update applied: (*channeldb.ChannelEdgePolicy)(0xc420f52240)({
 Signature: (*btcec.Signature)(0xc42031c5a0)({
  R: (*big.Int)(0xc42186d0e0)(39376065759288718121447882891715021409573473355047683250571213734036453045661),
  S: (*big.Int)(0xc42186d100)(54907437417084211173434159770441463924819803419543930895338498864742775167319)
 }),
 ChannelID: (uint64) 1322007701265448960,
 LastUpdate: (time.Time) 2017-09-27 06:37:44 +0200 CEST,
 Flags: (lnwire.ChanUpdateFlag) 1,
 TimeLockDelta: (uint16) 144,
 MinHTLC: (lnwire.MilliSatoshi) 0 mSAT,
 FeeBaseMSat: (lnwire.MilliSatoshi) 1000 mSAT,
 FeeProportionalMillionths: (lnwire.MilliSatoshi) 1 mSAT,
 Node: (*channeldb.LightningNode)(<nil>),
 db: (*channeldb.DB)(<nil>)
})

2017-12-27 13:53:49.609 [INF] CRTR: New channel update applied: (*channeldb.ChannelEdgePolicy)(0xc420d22600)({
 Signature: (*btcec.Signature)(0xc420856160)({
  R: (*big.Int)(0xc421acc560)(7500935126344829098311239486404214975010324461169358514906590267720877177063),
  S: (*big.Int)(0xc421acc580)(19819746074914506242486688827699486231041985887838681845673541331080413125980)
 }),
 ChannelID: (uint64) 1330821386483728384,
 LastUpdate: (time.Time) 2017-10-17 19:26:15 +0200 CEST,
 Flags: (lnwire.ChanUpdateFlag) 1,
 TimeLockDelta: (uint16) 144,
 MinHTLC: (lnwire.MilliSatoshi) 0 mSAT,
 FeeBaseMSat: (lnwire.MilliSatoshi) 1000 mSAT,
 FeeProportionalMillionths: (lnwire.MilliSatoshi) 1 mSAT,
 Node: (*channeldb.LightningNode)(<nil>),
 db: (*channeldb.DB)(<nil>)
})

2017-12-27 13:53:49.636 [INF] CRTR: New channel update applied: (*channeldb.ChannelEdgePolicy)(0xc4217090e0)({
 Signature: (*btcec.Signature)(0xc4213fbf60)({
  R: (*big.Int)(0xc420e71ca0)(30658290488457115776012515996455153945492568794088810377774627798318976067655),
  S: (*big.Int)(0xc420e71cc0)(27315252740550278737101130918917756161804307901812006915146546305552122793420)
 }),
 ChannelID: (uint64) 1330821386483728384,
 LastUpdate: (time.Time) 2017-10-16 19:13:15 +0200 CEST,
 Flags: (lnwire.ChanUpdateFlag) 0,
 TimeLockDelta: (uint16) 144,
 MinHTLC: (lnwire.MilliSatoshi) 0 mSAT,
 FeeBaseMSat: (lnwire.MilliSatoshi) 1000 mSAT,
 FeeProportionalMillionths: (lnwire.MilliSatoshi) 1 mSAT,
 Node: (*channeldb.LightningNode)(<nil>),
 db: (*channeldb.DB)(<nil>)
})

2017-12-27 13:53:52.737 [ERR] HSWC: first message sent to sync should be ChannelReestablish, instead received: *lnwire.UpdateAddHTLC
2017-12-27 13:53:52.738 [INF] HSWC: Removing channel link with ChannelID(bd5d5996185e5efdac875fe87497c2bea23a48fc657339dcacc8845176ece347)
2017-12-27 13:53:52.738 [INF] HSWC: ChannelLink(47e3ec765184c8acdc397365fc483aa2bec29774e85f87acfd5e5e1896595dbd:0) is stopping
2017-12-27 13:53:52.738 [INF] PEER: unable to read message from 96.250.224.65:56695: read tcp 37.205.8.78:9735->96.250.224.65:56695: use of closed network connection
2017-12-27 13:53:52.738 [INF] HSWC: ChannelLink(47e3ec765184c8acdc397365fc483aa2bec29774e85f87acfd5e5e1896595dbd:0) has exited
2017-12-27 13:53:52.738 [INF] NTFN: Cancelling epoch notification, epoch_id=157
2017-12-27 13:53:53.069 [INF] SRVR: New inbound connection from 96.250.224.65:56712
2017-12-27 13:53:53.097 [INF] NTFN: New spend subscription: utxo=47e3ec765184c8acdc397365fc483aa2bec29774e85f87acfd5e5e1896595dbd:0
2017-12-27 13:53:53.098 [INF] PEER: peerID(694) loading ChannelPoint(47e3ec765184c8acdc397365fc483aa2bec29774e85f87acfd5e5e1896595dbd:0)
2017-12-27 13:53:53.098 [INF] LNWL: Close observer for ChannelPoint(47e3ec765184c8acdc397365fc483aa2bec29774e85f87acfd5e5e1896595dbd:0) active
2017-12-27 13:53:53.098 [INF] BRAR: ChannelPoint(47e3ec765184c8acdc397365fc483aa2bec29774e85f87acfd5e5e1896595dbd:0) is now live, abandoning state contract for live version
2017-12-27 13:53:53.098 [INF] NTFN: New block epoch subscription
2017-12-27 13:53:53.098 [INF] NTFN: Cancelling spend notification for out_point=47e3ec765184c8acdc397365fc483aa2bec29774e85f87acfd5e5e1896595dbd:0, spend_id=172
2017-12-27 13:53:53.130 [INF] HSWC: ChannelLink(47e3ec765184c8acdc397365fc483aa2bec29774e85f87acfd5e5e1896595dbd:0) is starting
2017-12-27 13:53:53.131 [INF] HSWC: Added channel link with chan_id=bd5d5996185e5efdac875fe87497c2bea23a48fc657339dcacc8845176ece347, short_chan_id=((lnwire.ShortChannelID) 1256133:122:0
)
2017-12-27 13:53:53.131 [INF] HSWC: HTLC manager for ChannelPoint(47e3ec765184c8acdc397365fc483aa2bec29774e85f87acfd5e5e1896595dbd:0) started, bandwidth=0 mSAT
2017-12-27 13:53:53.131 [INF] HSWC: Attempting to re-resynchronize ChannelPoint(47e3ec765184c8acdc397365fc483aa2bec29774e85f87acfd5e5e1896595dbd:0)
2017-12-27 13:53:53.367 [INF] HSWC: ChannelPoint(47e3ec765184c8acdc397365fc483aa2bec29774e85f87acfd5e5e1896595dbd:0): resending FundingLocked message to peer
2017-12-27 13:53:53.369 [INF] HSWC: Received re-establishment message from remote side for channel(47e3ec765184c8acdc397365fc483aa2bec29774e85f87acfd5e5e1896595dbd:0)
2017-12-27 13:53:53.681 [ERR] HSWC: unable to find appropriate channel link insufficient capacity, need 324042400 mSAT
2017-12-27 13:53:53.682 [ERR] HSWC: channel link(47e3ec765184c8acdc397365fc483aa2bec29774e85f87acfd5e5e1896595dbd:0): unhandled error while forwarding htlc packet over htlc  switch: unable to find appropriate channel link insufficient capacity, need 324042400 mSAT
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x48 pc=0x8c474d]

goroutine 3668485 [running]:
github.com/lightningnetwork/lnd/lnwallet.(*LightningChannel).logUpdateToPayDesc(0xc4208c81c0, 0xc420fc9610, 0xc4208a0bd0, 0x2, 0x2ee0, 0xc420f53ec0, 0x23d, 0xc4208e3680, 0xc4208e36a0, 0xc4208e3660)
        /root/go/src/github.com/lightningnetwork/lnd/lnwallet/channel.go:1459 +0x5dd
github.com/lightningnetwork/lnd/lnwallet.(*LightningChannel).restoreStateLogs(0xc4208c81c0, 0xc42020c600, 0xc42020c6c0, 0xc42020c780, 0xc4201b8f00, 0xc420f53ec0, 0x0, 0x0)
        /root/go/src/github.com/lightningnetwork/lnd/lnwallet/channel.go:1668 +0x6ef
github.com/lightningnetwork/lnd/lnwallet.(*LightningChannel).restoreCommitState(0xc4208c81c0, 0xc420fc9a70, 0xc420fc99f0, 0xc4208a0b10, 0xc4208a0bd0, 0x21, 0xc420b80600)
        /root/go/src/github.com/lightningnetwork/lnd/lnwallet/channel.go:1586 +0x48c
github.com/lightningnetwork/lnd/lnwallet.NewLightningChannel(0x1462de0, 0xc4201c8120, 0x146b7c0, 0xc4201fc0e0, 0x14698a0, 0xc4201fa110, 0xc4207f1180, 0x1010901212a5800, 0x0, 0xc421296b78)
        /root/go/src/github.com/lightningnetwork/lnd/lnwallet/channel.go:1286 +0xa30
main.lndMain.func6(0xfd5e5e1896595dbd, 0xbec29774e85f87ac, 0xdc397365fc483aa2, 0x47e3ec765184c8ac, 0x0, 0x2, 0xc4213ea6f1)
        /root/go/src/github.com/lightningnetwork/lnd/lnd.go:290 +0x302
main.(*fundingManager).handleFundingLocked(0xc420194300, 0xc421916220)
        /root/go/src/github.com/lightningnetwork/lnd/fundingmanager.go:1952 +0x455
created by main.(*fundingManager).reservationCoordinator
        /root/go/src/github.com/lightningnetwork/lnd/fundingmanager.go:700 +0x490
Roasbeef commented 6 years ago

Thanks for this report! I've been trying to track this bug down for some time now, and I think your set of logs (combined with the other reports I've received), should help in pinning this bug.

alexbosworth commented 6 years ago

Similar

2017-12-29 20:45:15.850 [INF] HSWC: ChannelLink(6130eb2259237dee3ba526aae5f07b0b35d0c0329dcc78c5055b7732a87770ea:0) has exited
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x8d4ec0]

goroutine 11327195 [running]:
github.com/lightningnetwork/lnd/lnwallet.(*LightningChannel).evaluateHTLCView(0xc420bcb180, 0xc421cef920, 0xc421acf620, 0xc421acf618, 0x7, 0xc4212f3b01, 0xc4213f8820)
    /root/go/src/github.com/lightningnetwork/lnd/lnwallet/channel.go:2528 +0x820
github.com/lightningnetwork/lnd/lnwallet.(*LightningChannel).fetchCommitmentView(0xc420bcb180, 0x1, 0x3, 0x0, 0x2, 0x2, 0xc421124480, 0x4cb16f, 0xc4205dc1c0, 0x0)
    /root/go/src/github.com/lightningnetwork/lnd/lnwallet/channel.go:2292 +0x199
github.com/lightningnetwork/lnd/lnwallet.(*LightningChannel).SignNextCommitment(0xc420bcb180, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
    /root/go/src/github.com/lightningnetwork/lnd/lnwallet/channel.go:2962 +0x29e
github.com/lightningnetwork/lnd/htlcswitch.(*channelLink).updateCommitTx(0xc4205831d0, 0xc42080a000, 0x0)
    /root/go/src/github.com/lightningnetwork/lnd/htlcswitch/link.go:987 +0x44
github.com/lightningnetwork/lnd/htlcswitch.(*channelLink).htlcManager(0xc4205831d0)
    /root/go/src/github.com/lightningnetwork/lnd/htlcswitch/link.go:538 +0x6fc
created by github.com/lightningnetwork/lnd/htlcswitch.(*channelLink).Start
    /root/go/src/github.com/lightningnetwork/lnd/htlcswitch/link.go:267 +0x12b
whizz commented 6 years ago

Right now, I have the daemon in a state, that it crashes immediately after starting up and opening the wallet.

This is the entire log. I can run it with some more logging if you want.

2018-01-03 14:49:46.093 [INF] LTND: Version 0.3.0-alpha
2018-01-03 14:49:46.101 [INF] CHDB: Checking for schema update: latest_version=0, db_version=0
2018-01-03 14:49:46.193 [INF] RPCS: password RPC server listening on 127.0.0.1:10009
2018-01-03 14:49:46.198 [INF] RPCS: password gRPC proxy started at localhost:8080
2018-01-03 14:49:46.200 [INF] LTND: Waiting for wallet encryption password. Use `lncli create` to create wallet, or `lncli unlock` to unlock already created wallet.
2018-01-03 14:50:20.302 [INF] LNWL: Opened wallet
2018-01-03 14:50:20.304 [INF] LTND: Primary chain is set to: bitcoin
2018-01-03 14:50:20.332 [INF] LTND: Initializing btcd backed fee estimator
2018-01-03 14:50:22.310 [INF] LNWL: Opened wallet
2018-01-03 14:50:24.578 [INF] LNWL: The wallet has been unlocked without a time limit
2018-01-03 14:50:24.867 [INF] LTND: LightningWallet opened
2018-01-03 14:50:24.873 [INF] LNWL: Started rescan from block 00000000958954c5a0e2a0cd3b780a58eac8cbffe3455962ffcc84e6ced1343c (height 1257184) for 957 addresses
2018-01-03 14:50:24.974 [INF] LNWL: Catching up block hashes to height 1257184, this might take a while
2018-01-03 14:50:24.986 [INF] LNWL: Done catching up block hashes
2018-01-03 14:50:24.988 [INF] LNWL: Finished rescan for 957 addresses (synced to block 00000000958954c5a0e2a0cd3b780a58eac8cbffe3455962ffcc84e6ced1343c, height 1257184)
2018-01-03 14:50:25.352 [INF] RPCS: RPC server listening on 127.0.0.1:10009
2018-01-03 14:50:25.355 [INF] SRVR: Attempting to send msgs 1 to: 02c8ed754b0291755a296274cf52900f09dee1e5a2b8f7c6b6e2496a9ba5c7d86a
2018-01-03 14:50:25.357 [ERR] SRVR: unable to send message to 02c8ed754b0291755a296274cf52900f09dee1e5a2b8f7c6b6e2496a9ba5c7d86a, peer not found
2018-01-03 14:50:25.356 [INF] LTND: Waiting for chain backend to finish sync, start_height=1257184
2018-01-03 14:50:25.359 [WRN] FNDG: unable to send fundingLocked to peer 02c8ed754b0291755a296274cf52900f09dee1e5a2b8f7c6b6e2496a9ba5c7d86a: unable to find peer. Will retry when online
2018-01-03 14:50:25.359 [INF] RPCS: gRPC proxy started at localhost:8080
2018-01-03 14:50:25.360 [INF] SRVR: Attempting to send msgs 1 to: 0205135c541acd6b5f26a032b0508b1633a21ce0f27529b6773c5209c022e5f2c0
2018-01-03 14:50:25.367 [ERR] SRVR: unable to send message to 0205135c541acd6b5f26a032b0508b1633a21ce0f27529b6773c5209c022e5f2c0, peer not found
2018-01-03 14:50:25.367 [WRN] FNDG: unable to send fundingLocked to peer 0205135c541acd6b5f26a032b0508b1633a21ce0f27529b6773c5209c022e5f2c0: unable to find peer. Will retry when online
2018-01-03 14:50:25.372 [INF] LTND: Chain backend is fully synced (end_height=1257184)!
2018-01-03 14:50:25.599 [INF] HSWC: Starting HTLC Switch
2018-01-03 14:50:25.604 [INF] NTFN: New confirmations subscription: txid=508e4e5003e30e1040e75e299e4565f77a663e93093a8b64f485f55eaeaf9acc, numconfs=6
2018-01-03 14:50:25.716 [INF] NTFN: Dispatching 6 conf notification for 508e4e5003e30e1040e75e299e4565f77a663e93093a8b64f485f55eaeaf9acc
2018-01-03 14:50:25.717 [INF] NTFN: New confirmations subscription: txid=508e4e5003e30e1040e75e299e4565f77a663e93093a8b64f485f55eaeaf9acc, numconfs=6
2018-01-03 14:50:25.718 [INF] FNDG: Announcing ChannelPoint(508e4e5003e30e1040e75e299e4565f77a663e93093a8b64f485f55eaeaf9acc:0), short_chan_id=(*lnwire.ShortChannelID)(0xc420482710)(1257181:143:1)

2018-01-03 14:50:25.728 [INF] NTFN: Dispatching 6 conf notification for 508e4e5003e30e1040e75e299e4565f77a663e93093a8b64f485f55eaeaf9acc
2018-01-03 14:50:25.730 [INF] NTFN: New block epoch subscription
2018-01-03 14:50:25.730 [INF] FNDG: Announcing ChannelPoint(508e4e5003e30e1040e75e299e4565f77a663e93093a8b64f485f55eaeaf9acc:0), short_chan_id=(*lnwire.ShortChannelID)(0xc420482800)(1257139:149:0)

2018-01-03 14:50:25.843 [INF] BRAR: Retrieved 72 channels from database, watching with vigilance!
2018-01-03 14:50:25.851 [INF] NTFN: New spend subscription: utxo=0a03b05d0c4583a74d6cdc658676a6af8e680305272981271397785ad4c94c5a:0
2018-01-03 14:50:25.858 [INF] LNWL: Close observer for ChannelPoint(0a03b05d0c4583a74d6cdc658676a6af8e680305272981271397785ad4c94c5a:0) active
2018-01-03 14:50:25.861 [INF] NTFN: New spend subscription: utxo=9a5c78dfc69cc255f95780cedc83836b172df4e62d60be493c3d711cbaf81581:0
2018-01-03 14:50:25.863 [INF] LNWL: Close observer for ChannelPoint(9a5c78dfc69cc255f95780cedc83836b172df4e62d60be493c3d711cbaf81581:0) active
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x48 pc=0x8c48a8]

goroutine 1 [running]:
github.com/lightningnetwork/lnd/lnwallet.(*LightningChannel).logUpdateToPayDesc(0xc42063a540, 0xc430616fc0, 0xc42059ef30, 0x8ad, 0xd200, 0xc4201e0ea0, 0x222, 0xc4406f0f00, 0xc4406f1340, 0xc4406f0ee0)
        /root/go/src/github.com/lightningnetwork/lnd/lnwallet/channel.go:1475 +0x738
github.com/lightningnetwork/lnd/lnwallet.(*LightningChannel).restoreStateLogs(0xc42063a540, 0xc4205e8780, 0xc4205e8840, 0xc4205e8900, 0xc4205ca6e0, 0xc4201e0ea0, 0x0, 0x0)
        /root/go/src/github.com/lightningnetwork/lnd/lnwallet/channel.go:1668 +0x6ef
github.com/lightningnetwork/lnd/lnwallet.(*LightningChannel).restoreCommitState(0xc42063a540, 0xc430617420, 0xc4306173a0, 0xc42059ee70, 0xc42059ef30, 0x21, 0xc43067d600)
        /root/go/src/github.com/lightningnetwork/lnd/lnwallet/channel.go:1586 +0x48c
github.com/lightningnetwork/lnd/lnwallet.NewLightningChannel(0x0, 0x0, 0x146b7c0, 0xc420516000, 0x14698a0, 0xc4205be080, 0xc430662500, 0xc42063a380, 0x0, 0x0)
        /root/go/src/github.com/lightningnetwork/lnd/lnwallet/channel.go:1286 +0xa30
main.(*breachArbiter).Start(0xc420228050, 0x0, 0x0)
        /root/go/src/github.com/lightningnetwork/lnd/breacharbiter.go:215 +0x41c
main.(*server).Start(0xc4201b8100, 0xe4f2a8, 0x2e)
        /root/go/src/github.com/lightningnetwork/lnd/server.go:409 +0xcd
main.lndMain(0x0, 0x0)
        /root/go/src/github.com/lightningnetwork/lnd/lnd.go:401 +0x15f3
main.main()
        /root/go/src/github.com/lightningnetwork/lnd/lnd.go:450 +0x36
zyp commented 6 years ago

@Roasbeef thinks I've ran into the same problem and asked me to add my logs here: node A, node B.

I restarted node B at around 01:37:27 and that resulted in crashing both nodes A and B. Immediately before restarting node B, this is what I saw and did. Before that, I tried to send a payment to node A which seemed to get stuck.

MDrollette commented 6 years ago

I just started seeing the same thing as @whizz and am unable to start lnd. It is running on a preemptible Google Compute instance. So there's a chance this state came about from an unclean shutdown when the instance was preempted. 

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x48 pc=0x8c3c08]

goroutine 1 [running]:
github.com/lightningnetwork/lnd/lnwallet.(*LightningChannel).logUpdateToPayDesc(0xc42117c8c0, 0xc421152fc0, 0xc420ad63c0, 0x197, 0xc350, 0xc420e93020, 0x23d, 0xc42159b240, 0xc42159b260, 0xc42159b220)
        /home/matt/go/src/github.com/lightningnetwork/lnd/lnwallet/channel.go:1475 +0x738
github.com/lightningnetwork/lnd/lnwallet.(*LightningChannel).restoreStateLogs(0xc42117c8c0, 0xc42048a0c0, 0xc42048a480, 0xc42108f800, 0xc420093d60, 0xc420e93020, 0x0, 0x0)
        /home/matt/go/src/github.com/lightningnetwork/lnd/lnwallet/channel.go:1668 +0x6ef
github.com/lightningnetwork/lnd/lnwallet.(*LightningChannel).restoreCommitState(0xc42117c8c0, 0xc421153420, 0xc4211533a0, 0xc420ad62d0, 0xc420ad63c0, 0x21, 0xc420191600)
        /home/matt/go/src/github.com/lightningnetwork/lnd/lnwallet/channel.go:1586 +0x48c
github.com/lightningnetwork/lnd/lnwallet.NewLightningChannel(0x0, 0x0, 0x146c7c0, 0xc4204942a0, 0x146a8a0, 0xc42016e3e0, 0xc4209c3b80, 0xc420bf8380, 0x0, 0x0)
        /home/matt/go/src/github.com/lightningnetwork/lnd/lnwallet/channel.go:1286 +0xa30
main.(*breachArbiter).Start(0xc420082140, 0x0, 0x0)
        /home/matt/go/src/github.com/lightningnetwork/lnd/breacharbiter.go:215 +0x41c
main.(*server).Start(0xc420488500, 0xe4f493, 0x2e)
        /home/matt/go/src/github.com/lightningnetwork/lnd/server.go:410 +0xcd
main.lndMain(0x0, 0x0)
        /home/matt/go/src/github.com/lightningnetwork/lnd/lnd.go:401 +0x15f3
main.main()
        /home/matt/go/src/github.com/lightningnetwork/lnd/lnd.go:450 +0x36