search

lightningnetwork / lnd

Lightning Network Daemon ⚡️
MIT License
7.63k stars 2.07k forks source link

Not valid transaction (dust) to be used as input for new channels... #2657

Closed LNBIG-COM closed 5 years ago

LNBIG-COM commented 5 years ago

Background

If node has a 1.5 BTC in wallet for example after a some open few channels API calls i have walletbalance as 0 and some pending channels has double spent outputs.

Your environment

Hello!

I have fresh version of LND but i regulary have problems with open channels through API. Can you research this problem details? For example today i openned few channels. Before i had 1.5 BTC but after few calls i had in walletbalance zero. I open channels by same API (Node.JS):

let res = await myNode.client.openChannelSync({
    //node_pubkey: Buffer.from(pubKey, 'hex'),
    node_pubkey_string: pubKey,
    local_funding_amount: amnt,
    push_sat: 0,
    sat_per_byte: 2,
    private: false,
    min_htlc_msat: 1,
    min_confs: 0,
    spend_unconfirmed: true
})

Today before openning i stopped and restarted the LND. I need to do it regulary because i regulary have stuck channels. Ok, i did it: stopped and started again the LND. After some minutes i called to open channels. After few calls i had zero walletbalance. After researchind i found some channels with not-croadcasted funding transactions. For example:

{
    "channel": {
        "remote_node_pub": "03021c5f5f57322740e4ee6936452add19dc7ea7ccf90635f95119ab82a62ae268",
        "channel_point": "624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b:0",
        "capacity": "4994574",
        "local_balance": "4990923",
        "remote_balance": "0"
    },
    "confirmation_height": 0,
    "commit_fee": "3651",
    "commit_weight": "600",
    "fee_per_kw": "5044"
},

And what i see in logs again:

$ grep 624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b ~/.lnd/mainnet-lnd-run.log 
2019-02-19 11:15:52.365 [INF] FNDG: Generated ChannelPoint(624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b:0) for pendingID(15352eb09082da640ad68e019dc45a445063be8eb5681bbfd84d289fae99b778)
2019-02-19 11:15:52.484 [INF] FNDG: Broadcasting funding tx for ChannelPoint(624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b:0): (*wire.MsgTx)(0xc0be76bdc0)({
2019-02-19 11:15:52.486 [INF] LNWL: Inserting unconfirmed transaction 624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b
2019-02-19 11:15:52.507 [ERR] FNDG: Unable to broadcast funding tx for ChannelPoint(624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b:0): Transaction rejected: output already spent
2019-02-19 11:15:52.507 [INF] CNCT: Creating new ChannelArbitrator for ChannelPoint(624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b:0)
2019-02-19 11:15:52.507 [INF] CNCT: ChannelArbitrator(624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b:0): starting state=StateDefault
2019-02-19 11:15:52.509 [INF] NTFN: New spend subscription: spend_id=357, outpoint=624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b:0, height_hint=563745
2019-02-19 11:15:52.518 [INF] FNDG: Finalizing pendingID(15352eb09082da640ad68e019dc45a445063be8eb5681bbfd84d289fae99b778) over ChannelPoint(624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b:0), waiting for channel open on-chain
2019-02-19 11:15:52.518 [INF] CNCT: Close observer for ChannelPoint(624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b:0) active
2019-02-19 11:15:52.518 [INF] NTFN: New confirmation subscription: txid=624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b, numconfs=3
2019-02-19 11:15:52.519 [INF] FNDG: Waiting for funding tx (624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b) to reach 3 confirmations
2019-02-19 11:15:52.731 [ERR] NTFN: Rescan to determine the spend details of 624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b:0 failed: transaction not found within range

I found the fund transaction in logs:

2019-02-19 11:15:52.484 [INF] FNDG: Broadcasting funding tx for ChannelPoint(624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b:0): (*wire.MsgTx)(0xc0be76bdc0)({
 Version: (int32) 1,
 TxIn: ([]*wire.TxIn) (len=4 cap=15) {
  (*wire.TxIn)(0xc0054fb6e0)({
   PreviousOutPoint: (wire.OutPoint) 27a635424bf0d124a2ec4b3e39d4650001c1d88f2feeed60544b3a228c3753c4:0,
   SignatureScript: ([]uint8) <nil>,
   Witness: (wire.TxWitness) (len=2 cap=2) {
    ([]uint8) (len=72 cap=144) {
     00000000  30 45 02 21 00 d0 a4 4e  10 ba 9f b2 a3 53 e6 4c  |0E.!...N.....S.L|
     00000010  a6 41 06 78 35 4f d5 c1  86 6c e0 1c eb ea 03 55  |.A.x5O...l.....U|
     00000020  e1 ae 42 18 9c 02 20 23  7c 2a fe 20 4a 17 b2 34  |..B... #|*. J..4|
     00000030  0c e5 76 aa d8 89 c6 cd  e1 ec 3e 25 b0 ac 68 6f  |..v.......>%..ho|
     00000040  53 2b 54 eb 16 34 ab 01                           |S+T..4..|
    },
    ([]uint8) (len=33 cap=33) {
     00000000  02 7a 71 96 d9 f2 92 d8  97 cf d6 ef 82 6e e4 02  |.zq..........n..|
     00000010  ca 6a a9 66 33 c6 27 82  d4 c6 50 88 8a 78 d5 70  |.j.f3.'...P..x.p|
     00000020  6c                                                |l|
    }
   },
   Sequence: (uint32) 4294967295
  }),
  (*wire.TxIn)(0xc0054fb680)({
   PreviousOutPoint: (wire.OutPoint) 44936ac77ca64509b782f1022c5661ec5436afa3b4e1cae3b6c1704125ab2f7b:0,
   SignatureScript: ([]uint8) <nil>,
   Witness: (wire.TxWitness) (len=2 cap=2) {
    ([]uint8) (len=71 cap=144) {
     00000000  30 44 02 20 2f 38 9e 8d  f1 a6 62 a6 ed 05 38 6a  |0D. /8....b...8j|
     00000010  11 f3 3d bb a9 a4 5d 85  9b 70 c2 b0 56 27 95 62  |..=...]..p..V'.b|
     00000020  bb b9 f1 37 02 20 03 13  0c 40 63 b4 ba 2b 31 1e  |...7. ...@c..+1.|
     00000030  22 5a 90 94 84 4f d3 40  e7 d6 3b 0c a9 fa 19 d9  |"Z...O.@..;.....|
     00000040  f9 97 7e a0 ac c3 01                              |..~....|
    },
    ([]uint8) (len=33 cap=33) {
     00000000  02 08 21 3f 07 8a 3b 42  da df 43 89 ee 17 dd e9  |..!?..;B..C.....|
     00000010  66 b4 c2 31 fc 68 b2 3f  33 fe 91 e1 f7 c5 28 1e  |f..1.h.?3.....(.|
     00000020  f2                                                |.|
    }
   },
   Sequence: (uint32) 4294967295
  }),
  (*wire.TxIn)(0xc0054fb740)({
   PreviousOutPoint: (wire.OutPoint) 80a4a4e49a16e145967ce2c8edbe746da3d6509ea37d74fbd9a9b9cc6dffe814:1,
   SignatureScript: ([]uint8) <nil>,
   Witness: (wire.TxWitness) (len=2 cap=2) {
    ([]uint8) (len=71 cap=144) {
     00000000  30 44 02 20 36 fa 2d b7  c9 e1 6c 5a 80 96 b3 86  |0D. 6.-...lZ....|
     00000010  60 8f af 49 51 56 82 1c  3e 3d 15 b6 e6 3f ad 55  |`..IQV..>=...?.U|
     00000020  7c 40 80 11 02 20 7d 65  fd ff 8b a4 a5 09 7a 5e  ||@... }e......z^|
     00000030  d2 2f 82 a2 7e 33 9b 26  d7 81 2d 1d 72 a4 e8 55  |./..~3.&..-.r..U|
     00000040  f7 68 65 02 af b5 01                              |.he....|
    },
    ([]uint8) (len=33 cap=33) {
     00000000  03 b8 98 31 54 08 78 c8  c7 16 60 5f e6 4a 99 1a  |...1T.x...`_.J..|
     00000010  cc 8c 81 ea a2 33 c3 79  00 2b 03 fc be 45 55 c3  |.....3.y.+...EU.|
     00000020  b6                                                |.|
    }
   },
   Sequence: (uint32) 4294967295
  }),
  (*wire.TxIn)(0xc0054fb7a0)({
   PreviousOutPoint: (wire.OutPoint) d282aba762494f535bab325c8316906b8137be764001508e2d595135c1aaf791:1,
   SignatureScript: ([]uint8) <nil>,
   Witness: (wire.TxWitness) (len=2 cap=2) {
    ([]uint8) (len=71 cap=144) {
     00000000  30 44 02 20 1d 18 a7 84  95 5c 54 dc ba eb 7f fa  |0D. .....\T.....|
     00000010  39 bc 42 0a 46 f5 34 e4  22 6b f0 23 1b 4c a4 05  |9.B.F.4."k.#.L..|
     00000020  14 d2 37 2b 02 20 56 35  1e ef df 46 b1 86 eb a2  |..7+. V5...F....|
     00000030  f0 f0 ef c1 3a 80 3a 7b  76 a0 57 9a 1f 92 00 9c  |....:.:{v.W.....|
     00000040  50 f6 dc f2 cb cf 01                              |P......|
    },
    ([]uint8) (len=33 cap=33) {
     00000000  02 f7 17 85 0a 2d 52 9e  f7 0e 3a d2 52 fe 06 41  |.....-R...:.R..A|
     00000010  2b bf 87 3a 12 f5 f4 c8  01 2b f2 b9 13 cd 6e 20  |+..:.....+....n |
     00000020  f5                                                |.|
    }
   },
   Sequence: (uint32) 4294967295
  })
 },
 TxOut: ([]*wire.TxOut) (len=2 cap=15) {
  (*wire.TxOut)(0xc03c2102e0)({
   Value: (int64) 4994574,
   PkScript: ([]uint8) (len=34 cap=500) {
    00000000  00 20 ea c3 ae 19 cc 07  2b eb 3e e3 71 b1 f6 cf  |. ......+.>.q...|
    00000010  b1 7a 72 57 4c 79 38 62  3a 03 7c 97 4b 5f 4e f3  |.zrWLy8b:.|.K_N.|
    00000020  b1 c4                                             |..|
   }
  }),
  (*wire.TxOut)(0xc063bbcee0)({
   Value: (int64) 43285291,
   PkScript: ([]uint8) (len=22 cap=500) {
    00000000  00 14 f4 c9 b4 81 64 9f  82 f9 21 e8 31 9f f9 bb  |......d...!.1...|
    00000010  94 84 39 34 f2 b7                                 |..94..|
   }
  })
 },
 LockTime: (uint32) 0
})

There are 4 inputs. Some input(s) was used before. Why the LND uses spent outputs? Ok, if it's error why the LND sees the error "Transaction rejected: output already spent" and after this: 

2019-02-19 11:15:52.507 [ERR] FNDG: Unable to broadcast funding tx for ChannelPoint(624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b:0): Transaction rejected: output already spent
2019-02-19 11:15:52.507 [INF] CNCT: Creating new ChannelArbitrator for ChannelPoint(624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b:0)
2019-02-19 11:15:52.507 [INF] CNCT: ChannelArbitrator(624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b:0): starting state=StateDefault
2019-02-19 11:15:52.509 [INF] NTFN: New spend subscription: spend_id=357, outpoint=624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b:0, height_hint=563745
2019-02-19 11:15:52.518 [INF] FNDG: Finalizing pendingID(15352eb09082da640ad68e019dc45a445063be8eb5681bbfd84d289fae99b778) over ChannelPoint(624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b:0), waiting for channel open on-chain
2019-02-19 11:15:52.518 [INF] CNCT: Close observer for ChannelPoint(624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b:0) active
2019-02-19 11:15:52.518 [INF] NTFN: New confirmation subscription: txid=624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b, numconfs=3
2019-02-19 11:15:52.519 [INF] FNDG: Waiting for funding tx (624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b) to reach 3 confirmations
2019-02-19 11:15:52.731 [ERR] NTFN: Rescan to determine the spend details of 624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b:0 failed: transaction not found within range

It's stupid behaviuor. It should delete this not-finished channel. But it does everything as the channel is normal. After this i have stuck channels and cannot open channels but i have there ~ 1 BTC :(

LNBIG-COM commented 5 years ago

What i had been writting this issue the walletbalance was changed from 0 to 109569699:

I had:

$ l walletbalance
{
    "total_balance": "0",
    "confirmed_balance": "0",
    "unconfirmed_balance": "0"
}

Now:

$ l walletbalance
{
    "total_balance": "109569699",
    "confirmed_balance": "0",
    "unconfirmed_balance": "109569699"
}

The pending channel is there same:

{
    "channel": {
        "remote_node_pub": "03021c5f5f57322740e4ee6936452add19dc7ea7ccf90635f95119ab82a62ae268",
        "channel_point": "624296d9ac5ba5f8469187cee9e2be87331d5b6bc86477f75287681a6b1d201b:0",
        "capacity": "4994574",
        "local_balance": "4990923",
        "remote_balance": "0"
    },
    "confirmation_height": 0,
    "commit_fee": "3651",
    "commit_weight": "600",
    "fee_per_kw": "5044"
},

But if i do:

mainnet-lncli listchaintxns|grep amount|sed -r -e 's#.*"(-?[0-9]+)".*#\1#'|awk '{s+=$1} END {print s}'

I have 157850279

So the 157850279-109569699=48280580 satoshies to be blocked some there. I think thay are blocked by same buggy pending channels. When i close these pending channels by force i have them in "waiting_close_channels" section forever. It's pending lnd hell...

LNBIG-COM commented 5 years ago

After some researching next:

I found that there is one input (as "spent") from funding transaction which caused the problem:

  (*wire.TxIn)(0xc0054fb680)({
   PreviousOutPoint: (wire.OutPoint) 44936ac77ca64509b782f1022c5661ec5436afa3b4e1cae3b6c1704125ab2f7b:0,
   SignatureScript: ([]uint8) <nil>,
   Witness: (wire.TxWitness) (len=2 cap=2) {
    ([]uint8) (len=71 cap=144) {
     00000000  30 44 02 20 2f 38 9e 8d  f1 a6 62 a6 ed 05 38 6a  |0D. /8....b...8j|
     00000010  11 f3 3d bb a9 a4 5d 85  9b 70 c2 b0 56 27 95 62  |..=...]..p..V'.b|
     00000020  bb b9 f1 37 02 20 03 13  0c 40 63 b4 ba 2b 31 1e  |...7. ...@c..+1.|
     00000030  22 5a 90 94 84 4f d3 40  e7 d6 3b 0c a9 fa 19 d9  |"Z...O.@..;.....|
     00000040  f9 97 7e a0 ac c3 01                              |..~....|
    },
    ([]uint8) (len=33 cap=33) {
     00000000  02 08 21 3f 07 8a 3b 42  da df 43 89 ee 17 dd e9  |..!?..;B..C.....|
     00000010  66 b4 c2 31 fc 68 b2 3f  33 fe 91 e1 f7 c5 28 1e  |f..1.h.?3.....(.|
     00000020  f2                                                |.|
    }
   },
   Sequence: (uint32) 4294967295
  }),

Now this transaction doesn't exist even in my bitcoin node pool

$ bitcoin-cli getrawtransaction 44936ac77ca64509b782f1022c5661ec5436afa3b4e1cae3b6c1704125ab2f7b
error code: -5
error message:
No such mempool or blockchain transaction. Use gettransaction for wallet transactions.

But the LND operated its:

$ grep 44936ac77ca64509b782f1022c5661ec5436afa3b4e1cae3b6c1704125ab2f7b ~/.lnd/mainnet-lnd-run.log 
2019-02-03 02:39:23.087 [INF] LNWL: Inserting unconfirmed transaction 44936ac77ca64509b782f1022c5661ec5436afa3b4e1cae3b6c1704125ab2f7b
   PreviousOutPoint: (wire.OutPoint) 44936ac77ca64509b782f1022c5661ec5436afa3b4e1cae3b6c1704125ab2f7b:0,
2019-02-08 18:23:26.700 [INF] LNWL: Inserting unconfirmed transaction 44936ac77ca64509b782f1022c5661ec5436afa3b4e1cae3b6c1704125ab2f7b
   PreviousOutPoint: (wire.OutPoint) 44936ac77ca64509b782f1022c5661ec5436afa3b4e1cae3b6c1704125ab2f7b:0,
   PreviousOutPoint: (wire.OutPoint) 44936ac77ca64509b782f1022c5661ec5436afa3b4e1cae3b6c1704125ab2f7b:0,
   PreviousOutPoint: (wire.OutPoint) 44936ac77ca64509b782f1022c5661ec5436afa3b4e1cae3b6c1704125ab2f7b:0,

This output was used not successfully before:

2019-02-14 12:10:28.217 [INF] FNDG: Broadcasting funding tx for ChannelPoint(3cccb218c6b21d81114c220ab17b64193c5d00ac3cc956c6693f361b9dd3c72e:0): (*wire.MsgTx)(0xc0053d9340)({
 Version: (int32) 1,
 TxIn: ([]*wire.TxIn) (len=2 cap=15) {
  (*wire.TxIn)(0xc0136f4720)({
   PreviousOutPoint: (wire.OutPoint) 44936ac77ca64509b782f1022c5661ec5436afa3b4e1cae3b6c1704125ab2f7b:0,
   SignatureScript: ([]uint8) <nil>,
   Witness: (wire.TxWitness) (len=2 cap=2) {
    ([]uint8) (len=72 cap=144) {
     00000000  30 45 02 21 00 8f 2a 5a  ac d6 e9 a8 e9 a7 54 5d  |0E.!..*Z......T]|
     00000010  f1 98 21 91 ea 96 70 56  ca 6c 9b b9 4e d3 17 05  |..!...pV.l..N...|
     00000020  38 86 0d c3 49 02 20 4b  fe 68 94 0c a4 f0 fd c6  |8...I. K.h......|
     00000030  52 64 e3 be 1a a4 d3 28  07 7a 6f b3 85 76 0a 37  |Rd.....(.zo..v.7|
     00000040  90 55 d9 11 a8 fa 4d 01                           |.U....M.|
    },
    ([]uint8) (len=33 cap=33) {
     00000000  02 08 21 3f 07 8a 3b 42  da df 43 89 ee 17 dd e9  |..!?..;B..C.....|
     00000010  66 b4 c2 31 fc 68 b2 3f  33 fe 91 e1 f7 c5 28 1e  |f..1.h.?3.....(.|
     00000020  f2                                                |.|
    }
   },
   Sequence: (uint32) 4294967295
  }),
  (*wire.TxIn)(0xc0136f47e0)({
   PreviousOutPoint: (wire.OutPoint) ba46a1bb623418e26794cef00d81a407c4df6c1c468e5e56d59d14ded207de82:0,
   SignatureScript: ([]uint8) <nil>,
   Witness: (wire.TxWitness) (len=2 cap=2) {
    ([]uint8) (len=71 cap=144) {
     00000000  30 44 02 20 7b e8 45 3c  56 6c 69 b4 0c da 0d 99  |0D. {.E<Vli.....|
     00000010  01 ac 0c c3 d3 b0 21 a4  0c db e2 4e 33 fb e8 79  |......!....N3..y|
     00000020  ba 73 8c 74 02 20 4f 60  fe 89 e3 81 ed 8e 4d 1c  |.s.t. O`......M.|
     00000030  3a 07 b8 6e ca ef c8 7b  ff fa b8 21 c1 b8 d6 ca  |:..n...{...!....|
     00000040  fc 35 c8 1f 49 f2 01                              |.5..I..|
    },
    ([]uint8) (len=33 cap=33) {
     00000000  03 43 15 46 9e 3c c5 12  43 3b d3 ab 89 ea 14 b5  |.C.F.<..C;......|
     00000010  c1 52 a8 06 33 78 55 af  05 a4 e9 3e a4 3f 2c 73  |.R..3xU....>.?,s|
     00000020  f8                                                |.|
    }
   },
   Sequence: (uint32) 4294967295
  })
 },
 TxOut: ([]*wire.TxOut) (len=2 cap=15) {
  (*wire.TxOut)(0xc0102a0e60)({
   Value: (int64) 1402700,
   PkScript: ([]uint8) (len=34 cap=500) {
    00000000  00 20 67 2c c5 92 1f 54  31 f3 ef 8c e5 9c 7e 85  |. g,...T1.....~.|
    00000010  fc d9 fb 56 54 0f b2 73  38 5b 80 a3 51 74 61 4c  |...VT..s8[..QtaL|
    00000020  50 70                                             |Pp|
   }
  }),
  (*wire.TxOut)(0xc0552c8d40)({
   Value: (int64) 7591353,
   PkScript: ([]uint8) (len=22 cap=500) {
    00000000  00 14 6d da c7 28 31 9f  3d ba 3d d9 9d 47 a6 95  |..m..(1.=.=..G..|
    00000010  0e ff 37 00 3e d1                                 |..7.>.|
   }
  })
 },
 LockTime: (uint32) 0
})

2019-02-14 12:10:28.217 [INF] LNWL: Inserting unconfirmed transaction 3cccb218c6b21d81114c220ab17b64193c5d00ac3cc956c6693f361b9dd3c72e
2019-02-14 12:10:28.230 [ERR] FNDG: Unable to broadcast funding tx for ChannelPoint(3cccb218c6b21d81114c220ab17b64193c5d00ac3cc956c6693f361b9dd3c72e:0): Transaction rejected: output already spent

And before before...:

2019-02-08 20:07:04.544 [INF] FNDG: Broadcasting funding tx for ChannelPoint(65b25b500a23b8dc23e09d73def24f8c5acda3cc7e346511a842742babd1c14a:0): (*wire.MsgTx)(0xc02c8643c0)({
 Version: (int32) 1,
 TxIn: ([]*wire.TxIn) (len=3 cap=15) {
  (*wire.TxIn)(0xc05ab1bda0)({
   PreviousOutPoint: (wire.OutPoint) 383dd3af3e95b9601441c10fa39f0ac514b5fcfbb43541881a5e8b1750cc85c0:0,
   SignatureScript: ([]uint8) <nil>,
   Witness: (wire.TxWitness) (len=2 cap=2) {
    ([]uint8) (len=72 cap=144) {
     00000000  30 45 02 21 00 e0 a9 f4  60 d6 56 3f 72 b0 3d ec  |0E.!....`.V?r.=.|
     00000010  7b 3d b7 f3 a0 27 90 85  3b e1 b6 15 db 4a 16 dd  |{=...'..;....J..|
     00000020  68 f7 d0 33 ca 02 20 03  33 4c bf 4e 35 3f d0 79  |h..3.. .3L.N5?.y|
     00000030  e9 70 f1 45 dd d6 53 3f  b2 2b 43 c4 49 a5 82 8a  |.p.E..S?.+C.I...|
     00000040  c8 2a c4 27 d2 a7 61 01                           |.*.'..a.|
    },
    ([]uint8) (len=33 cap=33) {
     00000000  03 73 68 e1 e3 9b 3c ac  1b 2e b3 8b 7f c6 91 5a  |.sh...<........Z|
     00000010  83 8d fc ef 54 3c f4 8d  21 71 f8 9a 58 ee fb 01  |....T<..!q..X...|
     00000020  48                                                |H|
    }
   },
   Sequence: (uint32) 4294967295
  }),
  (*wire.TxIn)(0xc05ab1be00)({
   PreviousOutPoint: (wire.OutPoint) 44936ac77ca64509b782f1022c5661ec5436afa3b4e1cae3b6c1704125ab2f7b:0,
   SignatureScript: ([]uint8) <nil>,
   Witness: (wire.TxWitness) (len=2 cap=2) {
    ([]uint8) (len=72 cap=144) {
     00000000  30 45 02 21 00 f3 cf aa  9a 6c ee 6e 1d ec 1c c0  |0E.!.....l.n....|
     00000010  8b 67 63 90 52 51 70 b2  26 f3 c1 65 a8 0d 29 f9  |.gc.RQp.&..e..).|
     00000020  8b fd e6 59 c0 02 20 47  76 88 87 d1 2f 66 51 51  |...Y.. Gv.../fQQ|
     00000030  de e5 c9 36 3f 9a 10 e8  c9 4d 88 78 26 93 6c 99  |...6?....M.x&.l.|
     00000040  c2 84 a9 37 58 e3 9f 01                           |...7X...|
    },
    ([]uint8) (len=33 cap=33) {
     00000000  02 08 21 3f 07 8a 3b 42  da df 43 89 ee 17 dd e9  |..!?..;B..C.....|
     00000010  66 b4 c2 31 fc 68 b2 3f  33 fe 91 e1 f7 c5 28 1e  |f..1.h.?3.....(.|
     00000020  f2                                                |.|
    }
   },
   Sequence: (uint32) 4294967295
  }),
  (*wire.TxIn)(0xc05ab1bec0)({
   PreviousOutPoint: (wire.OutPoint) 59546f47d03746519edcd10a29d1ff827906391428af6cd17cd807fdb6ba83f1:11,
   SignatureScript: ([]uint8) <nil>,
   Witness: (wire.TxWitness) (len=2 cap=2) {
    ([]uint8) (len=71 cap=144) {
     00000000  30 44 02 20 2e 6e d3 90  ea 7f 77 2b 1f dd b8 82  |0D. .n....w+....|
     00000010  04 be 9b 57 93 ed a5 86  60 82 df 2c 10 25 8c eb  |...W....`..,.%..|
     00000020  75 4e f6 3b 02 20 2f 0c  99 97 ea 54 f4 22 f8 44  |uN.;. /....T.".D|
     00000030  6b fc 8f e9 b5 db 8a ad  3e 44 a6 d1 47 8d 8b 29  |k.......>D..G..)|
     00000040  a9 25 5e 3b 22 92 01                              |.%^;"..|
    },
    ([]uint8) (len=33 cap=33) {
     00000000  02 42 f4 be 46 27 5f ec  8a 30 c7 8e b3 db c1 36  |.B..F'_..0.....6|
     00000010  72 70 93 95 3c ad 2b d8  ee bc 17 30 60 c0 58 57  |rp..<.+....0`.XW|
     00000020  2c                                                |,|
    }
   },
   Sequence: (uint32) 4294967295
  })
 },
 TxOut: ([]*wire.TxOut) (len=2 cap=15) {
  (*wire.TxOut)(0xc019fe8080)({
   Value: (int64) 2000000,
   PkScript: ([]uint8) (len=34 cap=500) {
    00000000  00 20 de f8 60 f9 de ce  3a ac 7a 00 82 ea 3e 62  |. ..`...:.z...>b|
    00000010  75 79 49 9f fd bc 14 61  86 15 6a d0 1a e9 18 b1  |uyI....a..j.....|
    00000020  ef c8                                             |..|
   }
  }),
  (*wire.TxOut)(0xc0192102e0)({
   Value: (int64) 99525015,
   PkScript: ([]uint8) (len=22 cap=500) {
    00000000  00 14 a1 5d bd 81 b7 a2  37 26 fb de 47 09 86 f1  |...]....7&..G...|
    00000010  26 88 87 2b d6 53                                 |&..+.S|
   }
  })
 },
 LockTime: (uint32) 0
})

2019-02-08 20:07:04.545 [INF] LNWL: Inserting unconfirmed transaction 65b25b500a23b8dc23e09d73def24f8c5acda3cc7e346511a842742babd1c14a
2019-02-08 20:07:04.559 [ERR] FNDG: Unable to broadcast funding tx for ChannelPoint(65b25b500a23b8dc23e09d73def24f8c5acda3cc7e346511a842742babd1c14a:0): Transaction rejected: output already spent

And the first appearance of this transaction with near lines:

2019-02-03 02:39:20.984 [ERR] CMGR: Can't accept connection: unable to accept connection from 18.184.80.120:52008: EOF
2019-02-03 02:39:22.397 [INF] CRTR: Pruning channel graph using block 0000000000000000002617bf1a74a29fd53c9313fa4859af6bd8c00b3ffa77b0 (height=561292)
2019-02-03 02:39:22.419 [INF] CRTR: Block 0000000000000000002617bf1a74a29fd53c9313fa4859af6bd8c00b3ffa77b0 (height=561292) closed 3 channels
2019-02-03 02:39:22.419 [INF] ATPL: Processing new external signal
2019-02-03 02:39:22.420 [INF] ATPL: Triggering attachment directive dispatch, total_funds=0.01068092 BTC
2019-02-03 02:39:22.925 [INF] NTFN: New block: height=561292, sha=0000000000000000002617bf1a74a29fd53c9313fa4859af6bd8c00b3ffa77b0
2019-02-03 02:39:22.927 [INF] UTXN: Attempting to graduate height=561292: num_kids=0, num_babies=0
2019-02-03 02:39:22.927 [INF] NTFN: Dispatching spend notification for outpoint=2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1 at height=561292
2019-02-03 02:39:22.928 [WRN] CNCT: Unprompted commitment broadcast for ChannelPoint(2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1) 
2019-02-03 02:39:22.928 [INF] CNCT: Unilateral close of ChannelPoint(2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1) detected
2019-02-03 02:39:22.929 [INF] SWPR: Sweep candidates at height=561292, yield 0 distinct txns
2019-02-03 02:39:22.930 [INF] CNCT: ChannelArbitrator(2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1): remote party has closed channel out on-chain
2019-02-03 02:39:23.000 [INF] NTFN: New confirmation subscription: txid=0049e3f9439fe3b630dd59fa38187537336450f50f6bf614fec229d375bd1d91, numconfs=1
2019-02-03 02:39:23.013 [INF] CNCT: ChannelArbitrator(2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1): still awaiting contract resolution
2019-02-03 02:39:23.062 [INF] NTFN: Dispatching 1 conf notification for 0049e3f9439fe3b630dd59fa38187537336450f50f6bf614fec229d375bd1d91
2019-02-03 02:39:23.070 [INF] SWPR: Creating sweep transaction for 1 inputs (0 CSV, 0 CLTV) using 2422 sat/kw
2019-02-03 02:39:23.071 [INF] CNCT: *contractcourt.commitSweepResolver(2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1): sweeping commit output with tx=(*wire.MsgTx)(0xc0373bc800)({
 Version: (int32) 2,
 TxIn: ([]*wire.TxIn) (len=1 cap=15) {
  (*wire.TxIn)(0xc04121a480)({
   PreviousOutPoint: (wire.OutPoint) 0049e3f9439fe3b630dd59fa38187537336450f50f6bf614fec229d375bd1d91:0,
   SignatureScript: ([]uint8) <nil>,
   Witness: (wire.TxWitness) (len=2 cap=2) {
    ([]uint8) (len=71 cap=144) {
     00000000  30 44 02 20 2f 24 03 56  af 2d 61 e6 2d 4a a0 cb  |0D. /$.V.-a.-J..|
     00000010  ce 6f 85 aa 42 59 1e f1  d2 c1 a8 1f 3e df 1d 97  |.o..BY......>...|
     00000020  3a c1 db 9b 02 20 69 19  6f 63 ba 7f 5c 60 cc 18  |:.... i.oc..\`..|
     00000030  58 c6 cf 5f f7 55 b3 ff  4d 62 fc 7d 61 2b 09 bb  |X.._.U..Mb.}a+..|
     00000040  f4 8a 4b 33 c3 cd 01                              |..K3...|
    },
    ([]uint8) (len=33 cap=33) {
     00000000  02 fb ca fe 71 ad 78 95  83 84 a0 20 ad c1 28 e0  |....q.x.... ..(.|
     00000010  c4 61 b8 95 69 6b b0 69  84 27 de 0d c4 98 22 f9  |.a..ik.i.'....".|
     00000020  7b                                                |{|
    }
   },
   Sequence: (uint32) 0
  })
 },
 TxOut: ([]*wire.TxOut) (len=1 cap=15) {
  (*wire.TxOut)(0xc038e9fe60)({
   Value: (int64) 289,
   PkScript: ([]uint8) (len=22 cap=500) {
    00000000  00 14 70 b5 12 34 2c fc  5a 2f 22 5d 95 ec b2 c6  |..p..4,.Z/"]....|
    00000010  d5 13 fe 37 ad e6                                 |...7..|
   }
  })
 },
 LockTime: (uint32) 0
})

2019-02-03 02:39:23.087 [INF] LNWL: Inserting unconfirmed transaction 44936ac77ca64509b782f1022c5661ec5436afa3b4e1cae3b6c1704125ab2f7b
2019-02-03 02:39:23.099 [ERR] CNCT: *contractcourt.commitSweepResolver(2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1): unable to publish sweep tx: -26: dust (code 64)
2019-02-03 02:39:23.099 [ERR] CNCT: ChannelArbitrator(2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1): unable to progress resolver: -26: dust (code 64)

So as i understand this 44936ac77ca64509b782f1022c5661ec5436afa3b4e1cae3b6c1704125ab2f7b transaction was not added in pool because it had small volume outputs. But the LND remembered it as valid transaction and uses even present time as input for new channels... It's bug!

LNBIG-COM commented 5 years ago

And in pendingchannels i see channel which will not be closed because it has dust output:

"pending_force_closing_channels": [
    {
        "channel": {
            "remote_node_pub": "037002744f4cf194c71c58848d21d56f1ec4c7645cd2f48d830925ffa827d016b9",
            "channel_point": "2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1",
            "capacity": "2500000",
            "local_balance": "1352",
            "remote_balance": "0"
        },
        "closing_txid": "0049e3f9439fe3b630dd59fa38187537336450f50f6bf614fec229d375bd1d91",
        "limbo_balance": "0",
        "maturity_height": 0,
        "blocks_til_maturity": 0,
        "recovered_balance": "0",
        "pending_htlcs": [
        ]
    }
],

Thus, all of the above is indirectly related to this channel in the closed state. It should not be!

And here today logs about this closing channel:

2019-02-19 10:09:50.149 [INF] CNCT: ChannelArbitrator(2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1): starting state=StateWaitingFullResolution
2019-02-19 10:09:51.118 [INF] CNCT: ChannelArbitrator(2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1): still awaiting contract resolution
2019-02-19 10:09:51.118 [INF] CNCT: ChannelArbitrator(2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1): relaunching 1 contract resolvers
2019-02-19 10:09:53.278 [ERR] CNCT: *contractcourt.commitSweepResolver(2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1): unable to publish sweep tx: -26: dust (code 64)
2019-02-19 10:09:53.278 [ERR] CNCT: ChannelArbitrator(2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1): unable to progress resolver: -26: dust (code 64)
2019-02-19 11:09:32.180 [INF] UTXN: NurseryReport: building nursery report for channel 2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1
2019-02-19 11:09:37.721 [INF] UTXN: NurseryReport: building nursery report for channel 2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1
2019-02-19 11:10:29.530 [INF] UTXN: NurseryReport: building nursery report for channel 2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1
2019-02-19 11:15:45.476 [INF] UTXN: NurseryReport: building nursery report for channel 2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1
2019-02-19 11:19:36.076 [INF] UTXN: NurseryReport: building nursery report for channel 2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1
2019-02-19 11:20:33.482 [INF] UTXN: NurseryReport: building nursery report for channel 2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1
2019-02-19 11:20:52.996 [INF] UTXN: NurseryReport: building nursery report for channel 2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1
2019-02-19 11:21:10.641 [INF] UTXN: NurseryReport: building nursery report for channel 2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1
2019-02-19 11:21:49.597 [INF] UTXN: NurseryReport: building nursery report for channel 2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1
2019-02-19 11:21:55.255 [INF] UTXN: NurseryReport: building nursery report for channel 2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1
2019-02-19 11:26:57.165 [INF] UTXN: NurseryReport: building nursery report for channel 2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1
2019-02-19 11:31:43.281 [INF] UTXN: NurseryReport: building nursery report for channel 2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1
2019-02-19 11:37:16.553 [INF] UTXN: NurseryReport: building nursery report for channel 2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1
2019-02-19 11:37:30.159 [INF] UTXN: NurseryReport: building nursery report for channel 2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1
2019-02-19 11:43:07.895 [INF] UTXN: NurseryReport: building nursery report for channel 2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1
2019-02-19 11:48:50.132 [INF] UTXN: NurseryReport: building nursery report for channel 2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1
2019-02-19 11:50:56.712 [INF] UTXN: NurseryReport: building nursery report for channel 2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1
2019-02-19 11:54:22.306 [INF] UTXN: NurseryReport: building nursery report for channel 2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1
2019-02-19 11:55:45.265 [INF] UTXN: NurseryReport: building nursery report for channel 2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1
2019-02-19 11:56:08.791 [INF] UTXN: NurseryReport: building nursery report for channel 2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1
2019-02-19 11:58:17.008 [INF] UTXN: NurseryReport: building nursery report for channel 2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1
2019-02-19 11:58:21.530 [INF] UTXN: NurseryReport: building nursery report for channel 2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1
2019-02-19 11:58:49.881 [INF] UTXN: NurseryReport: building nursery report for channel 2ebfb79a652c4e5cee9539dc849fd8472f4cb9cead1d9a4cac4e12b27e04f96b:1
wpaulino commented 5 years ago

@LNBIG-COM thanks for the detailed report! #2671 will prevent this from happening going forward. You can remove any invalid pending_open channels by using the AbandonChannel RPC available in a debug build of lnd. You should not force close those channels as that will just make things worse. Then, to recover the funds used within those invalid channels, you'll need to rescan your wallet to ensure it has an accurate view of the chain with the dropwtxmgr tool.

note added: abandonchannel is a dangerous command and can lead to loss of funds if used incorrectly - ask in the LND slack channel if unsure

wpaulino commented 5 years ago

As for the dust output, you can update to the current master branch, which will batch small outputs like this in order to sweep them.

LNBIG-COM commented 5 years ago

Thanks! As i understand now the PR #2671 was not merged yet with master? I will try it through one week. I already run before this problem the dropwtxmgr utility in all nodes. So i know some about utility. The abondobchannel i didn't run yet and know where is located lnd binary in debug mode.

What do you think about this: may be will the abandonchannel command be moved into a non-debug binary? I think this command is usefull while the LND is beta. It is very inconvenient to stop the lnd process in order to run another binary debug lnd file and them stop again and run non-debug binary. What do you think?

wpaulino commented 5 years ago

The reason behind it being available under a debug build is so that users running the production build don't just arbitrarily use the RPC whenever they run into an issue with a channel. Ideally this RPC should not even exist, but it does as a convenience for users to clean up channels that ran into bugs.