lightningnetwork / lnd

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

LND crashes after unlocking wallet: "Failed to graduate outputs at height=552497: transaction output has negative value of -301" #2283

Closed karldiab closed 5 years ago

karldiab commented 5 years ago

Background

LND has been running happily on my rpi3 for about 3 weeks. I would check in on it every 2 days or so because it seemed to lock itself after every 3-5 days (not sure if that's normal). I checked in yesterday to find it locked, I unlocked it and it started filtering blocks about ~300 back from head. When it got to the end it reported "Failed to graduate outputs at height=552497: transaction output has negative value of -301" then shut down. Upon restarting the same thing occurs. Can my channels be saved?

Dec 05 10:27:36 raspberrypi systemd[1]: Started lnd Lightning Node.
Dec 05 10:27:37 raspberrypi lnd[1572]: 2018-12-05 10:27:37.176 [INF] LTND: Version: 0.5.1-beta commit=, build=production, logging=default
Dec 05 10:27:37 raspberrypi lnd[1572]: 2018-12-05 10:27:37.177 [INF] LTND: Active chain: Bitcoin (network=mainnet)
Dec 05 10:27:37 raspberrypi lnd[1572]: 2018-12-05 10:27:37.179 [INF] CHDB: Checking for schema update: latest_version=6, db_version=6
Dec 05 10:27:37 raspberrypi lnd[1572]: 2018-12-05 10:27:37.185 [INF] RPCS: password RPC server listening on 127.0.0.1:10009
Dec 05 10:27:37 raspberrypi lnd[1572]: 2018-12-05 10:27:37.185 [INF] RPCS: password gRPC proxy started at 127.0.0.1:8080
Dec 05 10:27:37 raspberrypi lnd[1572]: 2018-12-05 10:27:37.185 [INF] LTND: Waiting for wallet encryption password. Use `lncli create` to create a wallet, `lncli unlock` to unlock an existing wallet, or `lncli changepassword` to change th
Dec 05 18:49:06 raspberrypi lnd[1572]: 2018-12-05 18:49:06.845 [INF] LNWL: Opened wallet
Dec 05 18:49:07 raspberrypi lnd[1572]: 2018-12-05 18:49:07.318 [INF] LTND: Primary chain is set to: bitcoin
Dec 05 18:49:07 raspberrypi lnd[1572]: 2018-12-05 18:49:07.551 [INF] LNWL: Started listening for bitcoind block notifications via ZMQ on tcp://127.0.0.1:28332
Dec 05 18:49:07 raspberrypi lnd[1572]: 2018-12-05 18:49:07.551 [INF] LNWL: Started listening for bitcoind transaction notifications via ZMQ on tcp://127.0.0.1:28333
Dec 05 18:49:07 raspberrypi lnd[1572]: 2018-12-05 18:49:07.556 [INF] LTND: Initializing bitcoind backed fee estimator
Dec 05 18:49:07 raspberrypi lnd[1572]: 2018-12-05 18:49:07.579 [DBG] LNWL: Using minimum fee rate of 253 sat/kw
Dec 05 18:49:13 raspberrypi lnd[1572]: 2018-12-05 18:49:13.811 [INF] LNWL: The wallet has been unlocked without a time limit
Dec 05 18:49:13 raspberrypi lnd[1572]: 2018-12-05 18:49:13.818 [INF] LTND: LightningWallet opened
Dec 05 18:49:13 raspberrypi lnd[1572]: 2018-12-05 18:49:13.819 [DBG] LNWL: Birthday block has already been verified: height=550614, hash=000000000000000000273254cba891d8a387ac14349878d42364c20c4cd3570e
Dec 05 18:49:13 raspberrypi lnd[1572]: 2018-12-05 18:49:13.850 [INF] HSWC: Restoring in-memory circuit state from disk
Dec 05 18:49:13 raspberrypi lnd[1572]: 2018-12-05 18:49:13.852 [INF] HSWC: Payment circuits loaded: num_pending=0, num_open=0
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.259 [INF] HSWC: Trimming open circuits for chan_id=550996:3347:0, start_htlc_id=3
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.261 [INF] HSWC: Trimming open circuits for chan_id=550991:248:0, start_htlc_id=0
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.261 [INF] HSWC: Trimming open circuits for chan_id=550886:338:0, start_htlc_id=0
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.261 [INF] HSWC: Trimming open circuits for chan_id=550893:1480:0, start_htlc_id=0
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.261 [INF] HSWC: Trimming open circuits for chan_id=550893:1450:1, start_htlc_id=0
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.261 [INF] HSWC: Trimming open circuits for chan_id=551001:1693:1, start_htlc_id=1
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.261 [INF] HSWC: Trimming open circuits for chan_id=551597:713:1, start_htlc_id=0
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.262 [INF] HSWC: Trimming open circuits for chan_id=550893:1481:0, start_htlc_id=0
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.262 [INF] HSWC: Trimming open circuits for chan_id=551620:3139:0, start_htlc_id=0
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.262 [INF] HSWC: Trimming open circuits for chan_id=552306:1963:1, start_htlc_id=0
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.262 [INF] HSWC: Trimming open circuits for chan_id=551645:1966:0, start_htlc_id=0
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.262 [INF] HSWC: Trimming open circuits for chan_id=550893:1451:1, start_htlc_id=0
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.262 [INF] HSWC: Trimming open circuits for chan_id=551981:1126:1, start_htlc_id=0
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.262 [INF] HSWC: Trimming open circuits for chan_id=550993:2054:0, start_htlc_id=0
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.262 [INF] HSWC: Trimming open circuits for chan_id=550893:1482:0, start_htlc_id=0
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.262 [INF] HSWC: Trimming open circuits for chan_id=550893:1476:0, start_htlc_id=2
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.262 [INF] HSWC: Trimming open circuits for chan_id=550997:1290:1, start_htlc_id=0
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.263 [INF] HSWC: Trimming open circuits for chan_id=551038:527:0, start_htlc_id=0
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.263 [INF] HSWC: Trimming open circuits for chan_id=552307:1191:0, start_htlc_id=11
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.263 [INF] HSWC: Trimming open circuits for chan_id=550893:2855:1, start_htlc_id=2
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.263 [INF] HSWC: Trimming open circuits for chan_id=550893:1484:0, start_htlc_id=0
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.263 [INF] HSWC: Trimming open circuits for chan_id=551005:240:1, start_htlc_id=2
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.263 [INF] HSWC: Trimming open circuits for chan_id=550898:415:1, start_htlc_id=1
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.263 [INF] HSWC: Trimming open circuits for chan_id=550893:1479:0, start_htlc_id=0
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.263 [INF] HSWC: Trimming open circuits for chan_id=550893:1449:1, start_htlc_id=0
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.263 [INF] HSWC: Trimming open circuits for chan_id=550885:106:0, start_htlc_id=3
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.264 [INF] HSWC: Trimming open circuits for chan_id=550893:1483:1, start_htlc_id=0
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.293 [INF] RPCS: RPC server listening on 127.0.0.1:10009
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.293 [INF] RPCS: gRPC proxy started at 127.0.0.1:8080
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.297 [INF] LTND: Waiting for chain backend to finish sync, start_height=552671
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.422 [INF] LNWL: Catching up block hashes to height 552671, this will take a while...
Dec 05 18:49:14 raspberrypi lnd[1572]: 2018-12-05 18:49:14.612 [INF] LNWL: Done catching up block hashes
Dec 05 18:49:15 raspberrypi lnd[1572]: 2018-12-05 18:49:15.150 [INF] LNWL: Started rescan from block 000000000000000000273254cba891d8a387ac14349878d42364c20c4cd3570e (height 550614) for 254 addresses
Dec 05 18:49:15 raspberrypi lnd[1572]: 2018-12-05 18:49:15.158 [INF] LNWL: Starting rescan from block 000000000000000000273254cba891d8a387ac14349878d42364c20c4cd3570e
Dec 05 18:49:15 raspberrypi lnd[1572]: 2018-12-05 18:49:15.979 [DBG] LNWL: Filtering block 550615 (0000000000000000000a988ddaf9f330a8ef4db1bae8df55db6906de231774c6) with 3155 transactions
...............................
Dec 05 10:26:08 raspberrypi lnd[569]: 2018-12-05 10:26:08.899 [DBG] LNWL: Filtering block 552612 (0000000000000000002a6c82033d3cdc992ebc836a31e23838fc5e9056fce6b6) with 1198 transactions
Dec 05 10:26:10 raspberrypi lnd[569]: 2018-12-05 10:26:10.014 [DBG] LNWL: Filtering block 552613 (00000000000000000007afc4335ea914038188c735c1dbe5f038ece6ca262e8b) with 1966 transactions
Dec 05 10:26:11 raspberrypi lnd[569]: 2018-12-05 10:26:11.745 [DBG] LNWL: Filtering block 552614 (0000000000000000002a63651fdfb666f24536c78ee4e0a8c02d73015095ddfd) with 2861 transactions
Dec 05 10:26:13 raspberrypi lnd[569]: 2018-12-05 10:26:13.597 [DBG] LNWL: Filtering block 552615 (0000000000000000000f9e41a730c38ae84db3d3d8cb68f847ccafa69c241b7e) with 2776 transactions
Dec 05 10:26:15 raspberrypi lnd[569]: 2018-12-05 10:26:15.318 [DBG] LNWL: Filtering block 552616 (0000000000000000000777e7a5df61bb6f3754051961804cd19a33c7816491ac) with 2681 transactions
Dec 05 10:26:16 raspberrypi lnd[569]: 2018-12-05 10:26:16.986 [DBG] LNWL: Filtering block 552617 (0000000000000000000ce16c8fe045457f04199467bf39db7370252bb49d6d6b) with 2779 transactions
Dec 05 10:26:18 raspberrypi lnd[569]: 2018-12-05 10:26:18.583 [DBG] LNWL: Filtering block 552618 (00000000000000000022f3d77a96990124987798606da79355476b6d77b1f44d) with 2609 transactions
Dec 05 10:26:20 raspberrypi lnd[569]: 2018-12-05 10:26:20.309 [DBG] LNWL: Filtering block 552619 (0000000000000000000779eb4c3e65a9139e747388880ff5d03dd415ac172589) with 2497 transactions
Dec 05 10:26:21 raspberrypi lnd[569]: 2018-12-05 10:26:21.919 [DBG] LNWL: Filtering block 552620 (00000000000000000008b5bd74f350375591bd0032a38b62346f510a0aa25da2) with 2429 transactions
Dec 05 10:26:23 raspberrypi lnd[569]: 2018-12-05 10:26:23.459 [DBG] LNWL: Filtering block 552621 (00000000000000000009c7def2204a6afd91cce642ad850e7f9595792347c67b) with 2690 transactions
Dec 05 10:26:23 raspberrypi lnd[569]: 2018-12-05 10:26:23.461 [DBG] LNWL: Unable to parse output script in b9cf1442a6cb8794ab0c9a0d00de478dca7710629251867c7e2ac3d61b3a91f4:2: opcode OP_DATA_75 requires 76 bytes, but script only has 39 re
Dec 05 10:26:25 raspberrypi lnd[569]: 2018-12-05 10:26:25.311 [DBG] LNWL: Filtering block 552622 (0000000000000000002efa061c460577ce9e153d8ef4aaf1e96618ae1528e54d) with 2430 transactions
Dec 05 10:26:26 raspberrypi lnd[569]: 2018-12-05 10:26:26.964 [DBG] LNWL: Filtering block 552623 (0000000000000000002dcba7319872e7e49b024997b9eb2894f76e797f4afaa3) with 2014 transactions
Dec 05 10:26:28 raspberrypi lnd[569]: 2018-12-05 10:26:28.678 [DBG] LNWL: Filtering block 552624 (00000000000000000019b143f9a533abcd230884da8e6c6c38a4d07974482ddf) with 2787 transactions
Dec 05 10:26:30 raspberrypi lnd[569]: 2018-12-05 10:26:30.462 [DBG] LNWL: Filtering block 552625 (00000000000000000027ec6ec6014218ee73a2e3ca799b8aeb8d09b982a37c97) with 1903 transactions
Dec 05 10:26:32 raspberrypi lnd[569]: 2018-12-05 10:26:32.070 [DBG] LNWL: Filtering block 552626 (0000000000000000003031a88b78124fabeb0b33a89830184143f3a6cbe51e67) with 2610 transactions
Dec 05 10:26:33 raspberrypi lnd[569]: 2018-12-05 10:26:33.750 [DBG] LNWL: Filtering block 552627 (00000000000000000009b2a3abe6b334015cce51232e60998f6682f92947ddd9) with 2760 transactions
Dec 05 10:26:34 raspberrypi lnd[569]: 2018-12-05 10:26:34.648 [INF] LNWL: Rescan finished at 550614 (000000000000000000273254cba891d8a387ac14349878d42364c20c4cd3570e)
Dec 05 10:26:34 raspberrypi lnd[569]: 2018-12-05 10:26:34.649 [INF] LNWL: Catching up block hashes to height 550614, this might take a while
Dec 05 10:26:34 raspberrypi lnd[569]: 2018-12-05 10:26:34.650 [INF] LNWL: Done catching up block hashes
Dec 05 10:26:34 raspberrypi lnd[569]: 2018-12-05 10:26:34.662 [INF] LNWL: Finished rescan for 253 addresses (synced to block 000000000000000000273254cba891d8a387ac14349878d42364c20c4cd3570e, height 550614)
Dec 05 10:26:35 raspberrypi lnd[569]: 2018-12-05 10:26:35.683 [INF] LTND: Chain backend is fully synced (end_height=552627)!
Dec 05 10:26:35 raspberrypi lnd[569]: 2018-12-05 10:26:35.753 [INF] NTFN: New block epoch subscription
Dec 05 10:26:35 raspberrypi lnd[569]: 2018-12-05 10:26:35.754 [INF] HSWC: Starting HTLC Switch
Dec 05 10:26:35 raspberrypi lnd[569]: 2018-12-05 10:26:35.765 [INF] NTFN: New block epoch subscription
Dec 05 10:26:36 raspberrypi lnd[569]: 2018-12-05 10:26:36.266 [INF] NTFN: New block epoch subscription
Dec 05 10:26:36 raspberrypi lnd[569]: 2018-12-05 10:26:36.322 [INF] UTXN: Processing outputs from missed blocks. Starting with blockHeight=552496, to current blockHeight=552627
Dec 05 10:26:36 raspberrypi lnd[569]: 2018-12-05 10:26:36.323 [DBG] UTXN: Attempting to graduate outputs at height=552497
Dec 05 10:26:36 raspberrypi lnd[569]: 2018-12-05 10:26:36.331 [INF] UTXN: Attempting to graduate height=552497: num_kids=1, num_babies=0
Dec 05 10:26:36 raspberrypi lnd[569]: 2018-12-05 10:26:36.387 [DBG] LNWL: Returning 3419 sat/kw for conf target of 6
Dec 05 10:26:36 raspberrypi lnd[569]: 2018-12-05 10:26:36.395 [INF] SWPR: Creating sweep transaction for 1 inputs (1 CSV, 0 CLTV) using 3419 sat/kw
Dec 05 10:26:36 raspberrypi lnd[569]: 2018-12-05 10:26:36.395 [ERR] UTXN: Failed to create sweep txn at height=552497
Dec 05 10:26:36 raspberrypi lnd[569]: 2018-12-05 10:26:36.395 [ERR] UTXN: Failed to graduate outputs at height=552497: transaction output has negative value of -301
Dec 05 10:26:36 raspberrypi lnd[569]: 2018-12-05 10:26:36.396 [INF] NTFN: Cancelling epoch notification, epoch_id=3
Dec 05 10:26:36 raspberrypi lnd[569]: 2018-12-05 10:26:36.396 [ERR] SRVR: unable to start server: transaction output has negative value of -301
Dec 05 10:26:36 raspberrypi systemd[1]: lnd.service: Main process exited, code=exited, status=1/FAILURE
Dec 05 10:26:36 raspberrypi systemd[1]: lnd.service: Unit entered failed state.
Dec 05 10:26:36 raspberrypi systemd[1]: lnd.service: Failed with result 'exit-code'.
Dec 05 10:27:36 raspberrypi systemd[1]: lnd.service: Service hold-off time over, scheduling restart.
Dec 05 10:27:36 raspberrypi systemd[1]: Stopped lnd Lightning Node.

Your environment

Steps to reproduce

Tell us how to reproduce this issue. Please provide stacktraces and links to code in question. Simply run lnd and unlock wallet.

Expected behaviour

Tell us what should happen I should be able to spend my precious satoshis 😢

Actual behaviour

Tell us what happens instead Crash.

wpaulino commented 5 years ago

The output attempting to be swept after fees ends up dipping below the dust limit (546 sats). This needs to be handled correctly within the sweeper.

wpaulino commented 5 years ago

Should be fixed by #1960.

cfromknecht commented 5 years ago

The logic is there in #1960 to handle this, but it probably won’t fix this immediately unless the fee rate comes down. Once it becomes economical, it will be swept

karldiab commented 5 years ago

The logic is there in #1960 to handle this, but it probably won’t fix this immediately unless the fee rate comes down. Once it becomes economical, it will be swept

So wait until PR #1960 is merged, update then try unlocking wallet when network fees are low? Any way I can fund an address in my wallet to bring that balance >0?

joostjager commented 5 years ago

At least it fixes it in that it doesn't crash anymore.

karldiab commented 5 years ago

Tried to fund my lnd wallet by sending BTC to an address I previously used to fund my LND with the hopes of giving it enough bits to pay for this sweep transaction. Initially it looked like it was working, while LND was resyncing it was reporting the unconfirmed balance that I sent to it. But once it finished syncing it still reported 22:13:03 raspberrypi lnd[6740]: transaction output has negative value of -224 then shut down. Now when I restart and unlock it, it immediately reports the "transaction output has negative value" message then shuts down rather than syncing first then shutting down. (Progress?)

Maybe I need to fund a specific address? Anyone have any ideas on how to find that address?

wpaulino commented 5 years ago

Funding your wallet will not help - we're attempting to sweep our output of the funding transaction directly.

This patch should allow you to start up if you re-compile lnd with it:

diff --git a/utxonursery.go b/utxonursery.go
index 3f8cc2f3..24bdb89b 100644
--- a/utxonursery.go
+++ b/utxonursery.go
@@ -888,7 +888,6 @@ func (u *utxoNursery) graduateClass(classHeight uint32) error {
            if err != nil {
                utxnLog.Errorf("Failed to create sweep txn at "+
                    "height=%d", classHeight)
-               return err
            }
        }
karldiab commented 5 years ago

Funding your wallet will not help - we're attempting to sweep our output of the funding transaction directly.

This patch should allow you to start up if you re-compile lnd with it:

index 3f8cc2f3..24bdb89b 100644
--- a/utxonursery.go
+++ b/utxonursery.go
@@ -888,7 +888,6 @@ func (u *utxoNursery) graduateClass(classHeight uint32) error {
          if err != nil {
              utxnLog.Errorf("Failed to create sweep txn at "+
                  "height=%d", classHeight)
-             return err
          }
      }

Thanks for the help! Do you know of any articles or instructions for how I can achieve this?

wpaulino commented 5 years ago

Apply the patch locally with git apply and compile lnd by following the install docs. Feel free to join our slack/IRC if you get stuck along the way.

karldiab commented 5 years ago

Applying the patch wasn't working for me, but I manually commented out that line in utxonursery.go and it's not working!! Thanks wpaulino!!

Hopefully my channels are still open after a week of inactivity

Edit: opps, bad typo: ***it's now working!!

Roasbeef commented 5 years ago

1960 has been merged, so this should be resolved.