lightningnetwork / lnd

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

Funds stuck in limbo - unable to sweep #2562

Closed Horndev closed 5 years ago

Horndev commented 5 years ago

Background

I am closing my first LND node which has gone through several updates to start a fresh node. So I'm closing all my channels (about 100 with around 2 BTC capacity) to get the funds out.

Most of the active channels were easy and they closed. The inactive channels I had to force close.

Your environment

Steps to reproduce

I also wrote some of this up here: https://www.zapread.com/Post/Detail/3784

I waited 48 hours after closing all channels, and then I went to send funds to my new node using --sweepall

I got the error that utxo were already spent, so I used the dropwtxn tool as described in https://github.com/lightningnetwork/lnd/issues/1494

I rescanned the wallet over the last several hours, and the ballance went from around 0.3 BTC remaining to about 0.05.

I look at pendingchannels:

pendingchannels
{
    "total_limbo_balance": "6753308",
    "pending_open_channels": [
    ],
    "pending_closing_channels": [
    ],
    "pending_force_closing_channels": [
        {
            "channel": {
                "remote_node_pub": "03cb7983dc247f9f81a0fa2dfa3ce1c255365f7279c8dd143e086ca333df10e278",
                "channel_point": "e09d8f55a50fe9a396e0f942eaee85e6ba870c72ffacae6f95b73d05d8a48404:0",
                "capacity": "16777215",
                "local_balance": "42501",
                "remote_balance": "0"
            },
            "closing_txid": "1fdf0393254efd7bdb937c339a01ece4f67e0f601f17681b9519abeefed5eb6d",
            "limbo_balance": "0",
            "maturity_height": 0,
            "blocks_til_maturity": 0,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        },
        {
            "channel": {
                "remote_node_pub": "020d41c5a32f06d7addc7378f2d4a6596358d8716a3eb5d5bbdd894a82a1fdd00c",
                "channel_point": "9cebba83a510e9b2d52bbaeb9986b9e57ba86ff7adec1310c6afda253334a408:0",
                "capacity": "58000",
                "local_balance": "602",
                "remote_balance": "0"
            },
            "closing_txid": "bcec52500748200ed0848ddfad1e9ed30f7ae1c552c528bbd9da69d52a291f59",
            "limbo_balance": "602",
            "maturity_height": 542671,
            "blocks_til_maturity": -18034,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        },
        {
            "channel": {
                "remote_node_pub": "03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f",
                "channel_point": "2a4683fed472f26b08e2567b46e99ab3e606ae2a1887e83cbaff82a7dc6af00c:0",
                "capacity": "2000000",
                "local_balance": "1468960",
                "remote_balance": "0"
            },
            "closing_txid": "e730488549fc7990f0e7ab72a7d8f2daefb6b89a97c5f77d673d1c1fbd5b3525",
            "limbo_balance": "0",
            "maturity_height": 0,
            "blocks_til_maturity": 0,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        },
        {
            "channel": {
                "remote_node_pub": "036487e0bd981617c674c2856fc0050472a0182838e0a4a1a67545c6cdee9f49a0",
                "channel_point": "883f4b2cc4629d495bff2accca14d389b6e76e5174cb7ffe6fc3fd3f3ff4f111:0",
                "capacity": "50000",
                "local_balance": "733",
                "remote_balance": "0"
            },
            "closing_txid": "5e2d590fcc48098ff6fe0dee6d6a2f624190fc80f0fd7964396c4e08c2526bf1",
            "limbo_balance": "733",
            "maturity_height": 527663,
            "blocks_til_maturity": -33042,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        },
        {
            "channel": {
                "remote_node_pub": "031678745383bd273b4c3dbefc8ffbf4847d85c2f62d3407c0c980430b3257c403",
                "channel_point": "e612b571044b5386d1c15babd701823ea164ab045a8a189552ea6739540c8d1b:1",
                "capacity": "5000000",
                "local_balance": "2586729",
                "remote_balance": "0"
            },
            "closing_txid": "e05b05e86a6d192645fa01365ef503b360d807d78575f0391e0d4aae326ea9af",
            "limbo_balance": "2586729",
            "maturity_height": 560735,
            "blocks_til_maturity": 30,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        },
        {
            "channel": {
                "remote_node_pub": "03a96577e4cf8cac96937f4bf2753f7bd71323af5563690c8ed39c4e058c66c6c7",
                "channel_point": "5dfc4e79307094c0ce821d2c67bc89f0bb9e12d47546fa69218196bc6beb3f21:1",
                "capacity": "50000",
                "local_balance": "579",
                "remote_balance": "0"
            },
            "closing_txid": "15ea01435c9d6fc9433d581254c507e74a89a7b6c9572f048011996a94724517",
            "limbo_balance": "579",
            "maturity_height": 560282,
            "blocks_til_maturity": -423,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        },
        {
            "channel": {
                "remote_node_pub": "0390b5d4492dc2f5318e5233ab2cebf6d48914881a33ef6a9c6bcdbb433ad986d0",
                "channel_point": "f567819c8f9526d62ce2d14eea91a707fe713a4e18ae0ad89a0dd303aea9b836:0",
                "capacity": "16777215",
                "local_balance": "0",
                "remote_balance": "0"
            },
            "closing_txid": "eea4b0d3af9c87a9c0e326bdb365d9d05e4a7402c78c0309ab1f5ed43c612883",
            "limbo_balance": "0",
            "maturity_height": 0,
            "blocks_til_maturity": 0,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        },
        {
            "channel": {
                "remote_node_pub": "023216c5b9a54b6179645c76b279ae267f3c6b2379b9f305d57c75065006a8e5bd",
                "channel_point": "8c6cc58b545ce59bfd24f91fdf683093851cad6dcb7fc1012176ef159158e839:1",
                "capacity": "2000000",
                "local_balance": "3100",
                "remote_balance": "0"
            },
            "closing_txid": "f079cc5275ec40dc6f60d07f212dc32692198876112791ee4d125afc3facc0e7",
            "limbo_balance": "0",
            "maturity_height": 0,
            "blocks_til_maturity": 0,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        },
        {
            "channel": {
                "remote_node_pub": "03da1c27ca77872ac5b3e568af30673e599a47a5e4497f85c7b5da42048807b3ed",
                "channel_point": "3f68225091c048722233e4e4c315a974a4de25c3fdf3aea3878a8a95f5d1d95c:0",
                "capacity": "16777215",
                "local_balance": "0",
                "remote_balance": "0"
            },
            "closing_txid": "ab9f295ee1f9f4775941561e0c45a27f9e018e358292dbbbe325303cdd1f5ca6",
            "limbo_balance": "0",
            "maturity_height": 0,
            "blocks_til_maturity": 0,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        },
        {
            "channel": {
                "remote_node_pub": "03c4bb19c3a388d790968328b0f0d187a1a28597d3ad082200a47baadfdb6aee8d",
                "channel_point": "e07afe293b20910363ad5b01bd7f0192f6bf88d385002e74ff8594bf29c4d888:1",
                "capacity": "50000",
                "local_balance": "573",
                "remote_balance": "0"
            },
            "closing_txid": "57addab6ccb2a6a1390367e02a1219f1a372e57295971193685459f4931af919",
            "limbo_balance": "573",
            "maturity_height": 560194,
            "blocks_til_maturity": -511,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        },
        {
            "channel": {
                "remote_node_pub": "0303a518845db99994783f606e6629e705cfaf072e5ce9a4d8bf9e249de4fbd019",
                "channel_point": "048ba1a20e4c1c7c1e1915ecb2af7ec653c0aef4303c9bb2e1566d63034a409b:0",
                "capacity": "9000000",
                "local_balance": "0",
                "remote_balance": "0"
            },
            "closing_txid": "3d8017538eb0b605edceb148dfd91e3b30203adcfdb7c68e8dee36ac85a880f2",
            "limbo_balance": "0",
            "maturity_height": 0,
            "blocks_til_maturity": 0,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        },
        {
            "channel": {
                "remote_node_pub": "024e09e8fc093d1d0a72e9daf0165d8c50ed5b0517413f93f644e41d56b55e7f6f",
                "channel_point": "4a1d62d72c8848c58fb90f5235670436489b21aa22774789288f79e6a2b1c3aa:1",
                "capacity": "1000000",
                "local_balance": "938201",
                "remote_balance": "0"
            },
            "closing_txid": "7a03fe4870bfb51dfec7a9ff311294d0d233c32feb9e6917ca559f503b2666bc",
            "limbo_balance": "938201",
            "maturity_height": 561640,
            "blocks_til_maturity": 935,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        },
        {
            "channel": {
                "remote_node_pub": "030995c0c0217d763c2274aa6ed69a0bb85fa2f7d118f93631550f3b6219a577f5",
                "channel_point": "2dcfbe36edb2c40d221356868ff415b3179deb3d39561a307a93f3307e83bebf:0",
                "capacity": "16777215",
                "local_balance": "0",
                "remote_balance": "0"
            },
            "closing_txid": "22332c93d07836d85ba638375a9cfe6fadba082e2d9931406b1f2cfef0236ed2",
            "limbo_balance": "0",
            "maturity_height": 0,
            "blocks_til_maturity": 0,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        },
        {
            "channel": {
                "remote_node_pub": "032679fec1213e5b0a23e066c019d7b991b95c6e4d28806b9ebd1362f9e32775cf",
                "channel_point": "54259ec27ef84973bb905611e5aa2b84f4a6ae40876c605cabfbb3545d4f33c1:0",
                "capacity": "9000000",
                "local_balance": "0",
                "remote_balance": "0"
            },
            "closing_txid": "7ee90c11739a72e976bb7a423f465d7a8d13acf583679b8f82f16c063344d0b9",
            "limbo_balance": "0",
            "maturity_height": 0,
            "blocks_til_maturity": 0,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        },
        {
            "channel": {
                "remote_node_pub": "02c12b5459cf107ee0440cae41902f1189db50fa003a077f3a6fbe6b5760218695",
                "channel_point": "39389828ccded50ad1d380ee0fc59c9f9fa7224f4fe6bfe2c58c6772592b34c8:1",
                "capacity": "16777215",
                "local_balance": "226977",
                "remote_balance": "0"
            },
            "closing_txid": "3b4d9999553ac56561fb49a38d8adf327cf0051f210150edde7e0f36111a1ae4",
            "limbo_balance": "226977",
            "maturity_height": 562216,
            "blocks_til_maturity": 1511,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        },
        {
            "channel": {
                "remote_node_pub": "0332052748755d74b3395b91eaea78b53bd64b55eb031ccb6a7ae23ac445bb6af7",
                "channel_point": "f5c6598c5ad95bdd7335eeb2ec8f8cda4829d7bdb974447216edfc8f3c3df9ee:1",
                "capacity": "3000000",
                "local_balance": "2998914",
                "remote_balance": "0"
            },
            "closing_txid": "e0eb8dbca98a908d73f8f269bf53c0b67cb0eb09f76110de44f6b349352a1238",
            "limbo_balance": "2998914",
            "maturity_height": 561058,
            "blocks_til_maturity": 353,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        },
        {
            "channel": {
                "remote_node_pub": "02ad6fb8d693dc1e4569bcedefadf5f72a931ae027dc0f0c544b34c1c6f3b9a02b",
                "channel_point": "c51bab31943e3341429d89dd5f64b0b7ca66ab6326b9cde22737c52b56f9a6f5:1",
                "capacity": "1000000",
                "local_balance": "10116",
                "remote_balance": "0"
            },
            "closing_txid": "7c38faa34768b10618dba7fca71855f2e491eb9e30b8c81c0372ab03a631319c",
            "limbo_balance": "0",
            "maturity_height": 0,
            "blocks_til_maturity": 0,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        }
    ],
    "waiting_close_channels": [
    ]
}

Yes, there's a few recent transactions which I'm waiting to mature - it's the ones with 0 and negative blocks to maturity that I can't sweep.

Take the first one for example: The closing txn is confirmed a long time ago https://blockstream.info/tx/1fdf0393254efd7bdb937c339a01ece4f67e0f601f17681b9519abeefed5eb6d

It looks like it swept into https://blockstream.info/address/bc1qpwszjpd767a7d5he7l07wpdkhh92v4mkja9wxx

but, I can't see it in listchaintxns | grep bc1qpwszjpd767a7d5he7l07wpdkhh92v4mkja9wxx

Here is my log when starting up. You can see that LND tries to do a sweep, but it is not actually broadcast.

2019-01-30 02:12:23.121 [INF] LNWL: Inserting unconfirmed transaction 9df5c9a43b3f31c25d3ce02b14cabf4a84569f7823b6f16cb061a404606510e9
2019-01-30 02:12:23.143 [INF] NTFN: New block epoch subscription
2019-01-30 02:12:23.297 [INF] UTXN: (Re)-sweeping 4 heights below height=560705
2019-01-30 02:12:23.297 [INF] UTXN: Attempting to graduate height=527663: num_kids=1, num_babies=0
2019-01-30 02:12:23.297 [INF] UTXN: Sweeping 1 CSV-delayed outputs with sweep tx for height 527663
2019-01-30 02:12:23.297 [INF] SWPR: Sweep request received: out_point=5e2d590fcc48098ff6fe0dee6d6a2f624190fc80f0fd7964396c4e08c2526bf1:0, witness_type=CommitmentTimeLock, time_lock=144, size=0.00000733 BTC
2019-01-30 02:12:23.297 [INF] UTXN: Attempting to graduate height=542671: num_kids=1, num_babies=0
2019-01-30 02:12:23.297 [INF] UTXN: Sweeping 1 CSV-delayed outputs with sweep tx for height 542671
2019-01-30 02:12:23.297 [INF] SWPR: Sweep request received: out_point=bcec52500748200ed0848ddfad1e9ed30f7ae1c552c528bbd9da69d52a291f59:0, witness_type=CommitmentTimeLock, time_lock=144, size=0.00000602 BTC
2019-01-30 02:12:23.297 [INF] NTFN: New spend subscription: spend_id=1, outpoint=5e2d590fcc48098ff6fe0dee6d6a2f624190fc80f0fd7964396c4e08c2526bf1:0, height_hint=527519
2019-01-30 02:12:23.378 [INF] SWPR: Sweep candidates at height=560705, yield 0 distinct txns
2019-01-30 02:12:23.378 [INF] NTFN: New spend subscription: spend_id=2, outpoint=bcec52500748200ed0848ddfad1e9ed30f7ae1c552c528bbd9da69d52a291f59:0, height_hint=542527
2019-01-30 02:12:23.379 [INF] UTXN: Attempting to graduate height=560194: num_kids=1, num_babies=0
2019-01-30 02:12:23.379 [INF] UTXN: Sweeping 1 CSV-delayed outputs with sweep tx for height 560194
2019-01-30 02:12:23.379 [INF] SWPR: Sweep request received: out_point=57addab6ccb2a6a1390367e02a1219f1a372e57295971193685459f4931af919:0, witness_type=CommitmentTimeLock, time_lock=144, size=0.00000573 BTC
2019-01-30 02:12:23.493 [INF] SWPR: Sweep candidates at height=560705, yield 0 distinct txns
2019-01-30 02:12:23.493 [INF] NTFN: New spend subscription: spend_id=3, outpoint=57addab6ccb2a6a1390367e02a1219f1a372e57295971193685459f4931af919:0, height_hint=560050
2019-01-30 02:12:23.493 [INF] UTXN: Attempting to graduate height=560282: num_kids=1, num_babies=0
2019-01-30 02:12:23.493 [INF] UTXN: Sweeping 1 CSV-delayed outputs with sweep tx for height 560282
2019-01-30 02:12:23.493 [INF] SWPR: Sweep request received: out_point=15ea01435c9d6fc9433d581254c507e74a89a7b6c9572f048011996a94724517:0, witness_type=CommitmentTimeLock, time_lock=144, size=0.00000579 BTC
2019-01-30 02:12:23.601 [INF] SWPR: Sweep candidates at height=560705, yield 0 distinct txns
2019-01-30 02:12:23.601 [INF] NTFN: New spend subscription: spend_id=4, outpoint=15ea01435c9d6fc9433d581254c507e74a89a7b6c9572f048011996a94724517:0, height_hint=560138
2019-01-30 02:12:23.601 [INF] UTXN: UTXO Nursery is now fully synced
2019-01-30 02:12:23.601 [INF] NTFN: New block epoch subscription
2019-01-30 02:12:23.683 [INF] SWPR: Sweep candidates at height=560705, yield 0 distinct txns
2019-01-30 02:12:23.757 [INF] CNCT: Creating ChannelArbitrators for 17 closing channels
2019-01-30 02:12:23.757 [INF] NTFN: New block epoch subscription
2019-01-30 02:12:23.757 [INF] NTFN: New block epoch subscription
2019-01-30 02:12:23.757 [INF] NTFN: New block epoch subscription
2019-01-30 02:12:23.757 [INF] NTFN: New block epoch subscription
2019-01-30 02:12:23.757 [INF] NTFN: New block epoch subscription
2019-01-30 02:12:23.757 [INF] NTFN: New block epoch subscription
2019-01-30 02:12:23.757 [INF] NTFN: New block epoch subscription
2019-01-30 02:12:23.757 [INF] NTFN: New block epoch subscription
2019-01-30 02:12:23.757 [INF] NTFN: New block epoch subscription
2019-01-30 02:12:23.757 [INF] NTFN: New block epoch subscription
2019-01-30 02:12:23.757 [INF] NTFN: New block epoch subscription
2019-01-30 02:12:23.757 [INF] NTFN: New block epoch subscription
2019-01-30 02:12:23.757 [INF] NTFN: New block epoch subscription
2019-01-30 02:12:23.757 [INF] NTFN: New block epoch subscription
2019-01-30 02:12:23.757 [INF] NTFN: New block epoch subscription
2019-01-30 02:12:23.758 [INF] NTFN: New block epoch subscription
2019-01-30 02:12:23.758 [INF] NTFN: New block epoch subscription
2019-01-30 02:12:23.758 [INF] CNCT: ChannelArbitrator(5dfc4e79307094c0ce821d2c67bc89f0bb9e12d47546fa69218196bc6beb3f21:1): starting state=StateWaitingFullResolution
2019-01-30 02:12:23.759 [INF] CNCT: ChannelArbitrator(5dfc4e79307094c0ce821d2c67bc89f0bb9e12d47546fa69218196bc6beb3f21:1): still awaiting contract resolution
2019-01-30 02:12:23.759 [INF] CNCT: ChannelArbitrator(5dfc4e79307094c0ce821d2c67bc89f0bb9e12d47546fa69218196bc6beb3f21:1): relaunching 1 contract resolvers
2019-01-30 02:12:23.760 [INF] CNCT: ChannelArbitrator(e07afe293b20910363ad5b01bd7f0192f6bf88d385002e74ff8594bf29c4d888:1): starting state=StateWaitingFullResolution
2019-01-30 02:12:23.760 [INF] NTFN: New confirmation subscription: txid=15ea01435c9d6fc9433d581254c507e74a89a7b6c9572f048011996a94724517, num_confs=1
2019-01-30 02:12:23.761 [INF] CNCT: ChannelArbitrator(e07afe293b20910363ad5b01bd7f0192f6bf88d385002e74ff8594bf29c4d888:1): still awaiting contract resolution
2019-01-30 02:12:23.761 [INF] CNCT: ChannelArbitrator(e07afe293b20910363ad5b01bd7f0192f6bf88d385002e74ff8594bf29c4d888:1): relaunching 1 contract resolvers
2019-01-30 02:12:23.761 [INF] CNCT: ChannelArbitrator(4a1d62d72c8848c58fb90f5235670436489b21aa22774789288f79e6a2b1c3aa:1): starting state=StateWaitingFullResolution
2019-01-30 02:12:23.761 [INF] NTFN: New confirmation subscription: txid=57addab6ccb2a6a1390367e02a1219f1a372e57295971193685459f4931af919, num_confs=1
2019-01-30 02:12:23.762 [INF] CNCT: ChannelArbitrator(4a1d62d72c8848c58fb90f5235670436489b21aa22774789288f79e6a2b1c3aa:1): still awaiting contract resolution
2019-01-30 02:12:23.762 [INF] CNCT: ChannelArbitrator(4a1d62d72c8848c58fb90f5235670436489b21aa22774789288f79e6a2b1c3aa:1): relaunching 1 contract resolvers
2019-01-30 02:12:23.762 [INF] CNCT: ChannelArbitrator(2dcfbe36edb2c40d221356868ff415b3179deb3d39561a307a93f3307e83bebf:0): starting state=StateContractClosed
2019-01-30 02:12:23.762 [INF] NTFN: New confirmation subscription: txid=7a03fe4870bfb51dfec7a9ff311294d0d233c32feb9e6917ca559f503b2666bc, num_confs=1
2019-01-30 02:12:23.777 [ERR] CNCT: unable to fetch contract resolutions: no contract resolutions exist
2019-01-30 02:12:23.777 [ERR] CNCT: ChannelArbitrator(2dcfbe36edb2c40d221356868ff415b3179deb3d39561a307a93f3307e83bebf:0): unable to advance state: no contract resolutions exist
2019-01-30 02:12:23.777 [WRN] CNCT: ChannelArbitrator(2dcfbe36edb2c40d221356868ff415b3179deb3d39561a307a93f3307e83bebf:0): detected closedchannel with no contract resolutions written.
2019-01-30 02:12:23.777 [INF] CNCT: ChannelArbitrator(c51bab31943e3341429d89dd5f64b0b7ca66ab6326b9cde22737c52b56f9a6f5:1): starting state=StateContractClosed
2019-01-30 02:12:23.805 [ERR] CNCT: unable to fetch contract resolutions: no contract resolutions exist
2019-01-30 02:12:23.805 [ERR] CNCT: ChannelArbitrator(c51bab31943e3341429d89dd5f64b0b7ca66ab6326b9cde22737c52b56f9a6f5:1): unable to advance state: no contract resolutions exist
2019-01-30 02:12:23.805 [WRN] CNCT: ChannelArbitrator(c51bab31943e3341429d89dd5f64b0b7ca66ab6326b9cde22737c52b56f9a6f5:1): detected closedchannel with no contract resolutions written.
2019-01-30 02:12:23.805 [INF] CNCT: ChannelArbitrator(883f4b2cc4629d495bff2accca14d389b6e76e5174cb7ffe6fc3fd3f3ff4f111:0): starting state=StateWaitingFullResolution
2019-01-30 02:12:23.828 [INF] CNCT: ChannelArbitrator(883f4b2cc4629d495bff2accca14d389b6e76e5174cb7ffe6fc3fd3f3ff4f111:0): still awaiting contract resolution
2019-01-30 02:12:23.828 [INF] CNCT: ChannelArbitrator(883f4b2cc4629d495bff2accca14d389b6e76e5174cb7ffe6fc3fd3f3ff4f111:0): relaunching 1 contract resolvers
2019-01-30 02:12:23.828 [INF] CNCT: ChannelArbitrator(e612b571044b5386d1c15babd701823ea164ab045a8a189552ea6739540c8d1b:1): starting state=StateWaitingFullResolution
2019-01-30 02:12:23.829 [INF] NTFN: New confirmation subscription: txid=5e2d590fcc48098ff6fe0dee6d6a2f624190fc80f0fd7964396c4e08c2526bf1, num_confs=1
2019-01-30 02:12:23.830 [INF] CNCT: ChannelArbitrator(e612b571044b5386d1c15babd701823ea164ab045a8a189552ea6739540c8d1b:1): still awaiting contract resolution
2019-01-30 02:12:23.830 [INF] CNCT: ChannelArbitrator(e612b571044b5386d1c15babd701823ea164ab045a8a189552ea6739540c8d1b:1): relaunching 1 contract resolvers
2019-01-30 02:12:23.830 [INF] CNCT: ChannelArbitrator(3f68225091c048722233e4e4c315a974a4de25c3fdf3aea3878a8a95f5d1d95c:0): starting state=StateContractClosed
2019-01-30 02:12:23.831 [INF] NTFN: New confirmation subscription: txid=e05b05e86a6d192645fa01365ef503b360d807d78575f0391e0d4aae326ea9af, num_confs=1
2019-01-30 02:12:23.831 [ERR] CNCT: unable to fetch contract resolutions: no contract resolutions exist
2019-01-30 02:12:23.831 [ERR] CNCT: ChannelArbitrator(3f68225091c048722233e4e4c315a974a4de25c3fdf3aea3878a8a95f5d1d95c:0): unable to advance state: no contract resolutions exist
2019-01-30 02:12:23.831 [WRN] CNCT: ChannelArbitrator(3f68225091c048722233e4e4c315a974a4de25c3fdf3aea3878a8a95f5d1d95c:0): detected closedchannel with no contract resolutions written.
2019-01-30 02:12:23.831 [INF] CNCT: ChannelArbitrator(048ba1a20e4c1c7c1e1915ecb2af7ec653c0aef4303c9bb2e1566d63034a409b:0): starting state=StateContractClosed
2019-01-30 02:12:23.833 [ERR] CNCT: unable to fetch contract resolutions: no contract resolutions exist
2019-01-30 02:12:23.833 [ERR] CNCT: ChannelArbitrator(048ba1a20e4c1c7c1e1915ecb2af7ec653c0aef4303c9bb2e1566d63034a409b:0): unable to advance state: no contract resolutions exist
2019-01-30 02:12:23.833 [WRN] CNCT: ChannelArbitrator(048ba1a20e4c1c7c1e1915ecb2af7ec653c0aef4303c9bb2e1566d63034a409b:0): detected closedchannel with no contract resolutions written.
2019-01-30 02:12:23.833 [INF] CNCT: ChannelArbitrator(f5c6598c5ad95bdd7335eeb2ec8f8cda4829d7bdb974447216edfc8f3c3df9ee:1): starting state=StateWaitingFullResolution
2019-01-30 02:12:23.834 [INF] CNCT: ChannelArbitrator(f5c6598c5ad95bdd7335eeb2ec8f8cda4829d7bdb974447216edfc8f3c3df9ee:1): still awaiting contract resolution
2019-01-30 02:12:23.834 [INF] CNCT: ChannelArbitrator(f5c6598c5ad95bdd7335eeb2ec8f8cda4829d7bdb974447216edfc8f3c3df9ee:1): relaunching 1 contract resolvers
2019-01-30 02:12:23.834 [INF] CNCT: ChannelArbitrator(e09d8f55a50fe9a396e0f942eaee85e6ba870c72ffacae6f95b73d05d8a48404:0): starting state=StateContractClosed
2019-01-30 02:12:23.834 [INF] NTFN: New confirmation subscription: txid=e0eb8dbca98a908d73f8f269bf53c0b67cb0eb09f76110de44f6b349352a1238, num_confs=1
2019-01-30 02:12:23.835 [ERR] CNCT: unable to fetch contract resolutions: no contract resolutions exist
2019-01-30 02:12:23.835 [ERR] CNCT: ChannelArbitrator(e09d8f55a50fe9a396e0f942eaee85e6ba870c72ffacae6f95b73d05d8a48404:0): unable to advance state: no contract resolutions exist
2019-01-30 02:12:23.835 [WRN] CNCT: ChannelArbitrator(e09d8f55a50fe9a396e0f942eaee85e6ba870c72ffacae6f95b73d05d8a48404:0): detected closedchannel with no contract resolutions written.
2019-01-30 02:12:23.835 [INF] CNCT: ChannelArbitrator(9cebba83a510e9b2d52bbaeb9986b9e57ba86ff7adec1310c6afda253334a408:0): starting state=StateWaitingFullResolution
2019-01-30 02:12:23.836 [INF] CNCT: ChannelArbitrator(9cebba83a510e9b2d52bbaeb9986b9e57ba86ff7adec1310c6afda253334a408:0): still awaiting contract resolution
2019-01-30 02:12:23.836 [INF] CNCT: ChannelArbitrator(9cebba83a510e9b2d52bbaeb9986b9e57ba86ff7adec1310c6afda253334a408:0): relaunching 1 contract resolvers
2019-01-30 02:12:23.836 [INF] CNCT: ChannelArbitrator(f567819c8f9526d62ce2d14eea91a707fe713a4e18ae0ad89a0dd303aea9b836:0): starting state=StateContractClosed
2019-01-30 02:12:23.837 [INF] NTFN: New confirmation subscription: txid=bcec52500748200ed0848ddfad1e9ed30f7ae1c552c528bbd9da69d52a291f59, num_confs=1
2019-01-30 02:12:23.837 [ERR] CNCT: unable to fetch contract resolutions: no contract resolutions exist
2019-01-30 02:12:23.837 [ERR] CNCT: ChannelArbitrator(f567819c8f9526d62ce2d14eea91a707fe713a4e18ae0ad89a0dd303aea9b836:0): unable to advance state: no contract resolutions exist
2019-01-30 02:12:23.837 [WRN] CNCT: ChannelArbitrator(f567819c8f9526d62ce2d14eea91a707fe713a4e18ae0ad89a0dd303aea9b836:0): detected closedchannel with no contract resolutions written.
2019-01-30 02:12:23.837 [INF] CNCT: ChannelArbitrator(8c6cc58b545ce59bfd24f91fdf683093851cad6dcb7fc1012176ef159158e839:1): starting state=StateContractClosed
2019-01-30 02:12:23.838 [ERR] CNCT: unable to fetch contract resolutions: no contract resolutions exist
2019-01-30 02:12:23.838 [ERR] CNCT: ChannelArbitrator(8c6cc58b545ce59bfd24f91fdf683093851cad6dcb7fc1012176ef159158e839:1): unable to advance state: no contract resolutions exist
2019-01-30 02:12:23.838 [WRN] CNCT: ChannelArbitrator(8c6cc58b545ce59bfd24f91fdf683093851cad6dcb7fc1012176ef159158e839:1): detected closedchannel with no contract resolutions written.
2019-01-30 02:12:23.838 [INF] CNCT: ChannelArbitrator(54259ec27ef84973bb905611e5aa2b84f4a6ae40876c605cabfbb3545d4f33c1:0): starting state=StateContractClosed
2019-01-30 02:12:23.839 [ERR] CNCT: unable to fetch contract resolutions: no contract resolutions exist
2019-01-30 02:12:23.839 [ERR] CNCT: ChannelArbitrator(54259ec27ef84973bb905611e5aa2b84f4a6ae40876c605cabfbb3545d4f33c1:0): unable to advance state: no contract resolutions exist
2019-01-30 02:12:23.839 [WRN] CNCT: ChannelArbitrator(54259ec27ef84973bb905611e5aa2b84f4a6ae40876c605cabfbb3545d4f33c1:0): detected closedchannel with no contract resolutions written.
2019-01-30 02:12:23.839 [INF] CNCT: ChannelArbitrator(2a4683fed472f26b08e2567b46e99ab3e606ae2a1887e83cbaff82a7dc6af00c:0): starting state=StateWaitingFullResolution
2019-01-30 02:12:23.840 [INF] CNCT: ChannelArbitrator(2a4683fed472f26b08e2567b46e99ab3e606ae2a1887e83cbaff82a7dc6af00c:0): still awaiting contract resolution
2019-01-30 02:12:23.841 [INF] CNCT: ChannelArbitrator(2a4683fed472f26b08e2567b46e99ab3e606ae2a1887e83cbaff82a7dc6af00c:0): relaunching 1 contract resolvers
2019-01-30 02:12:23.841 [INF] CNCT: *contractcourt.htlcSuccessResolver(55932bb2f35fd5457cb1fa7c51d8f89ac8aa2163420b54e7f0509bdf1806f96e): crafting sweep tx for incoming+remote htlc confirmed
2019-01-30 02:12:23.841 [INF] CNCT: ChannelArbitrator(39389828ccded50ad1d380ee0fc59c9f9fa7224f4fe6bfe2c58c6772592b34c8:1): starting state=StateWaitingFullResolution
2019-01-30 02:12:23.842 [INF] CNCT: ChannelArbitrator(39389828ccded50ad1d380ee0fc59c9f9fa7224f4fe6bfe2c58c6772592b34c8:1): still awaiting contract resolution
2019-01-30 02:12:23.843 [INF] CNCT: ChannelArbitrator(39389828ccded50ad1d380ee0fc59c9f9fa7224f4fe6bfe2c58c6772592b34c8:1): relaunching 1 contract resolvers
2019-01-30 02:12:23.843 [INF] NTFN: New confirmation subscription: txid=3b4d9999553ac56561fb49a38d8adf327cf0051f210150edde7e0f36111a1ae4, num_confs=1
2019-01-30 02:12:23.904 [INF] SWPR: Creating sweep transaction for 1 inputs (0 CSV, 0 CLTV) using 2788 sat/kw
2019-01-30 02:12:23.905 [INF] CNCT: *contractcourt.htlcSuccessResolver(55932bb2f35fd5457cb1fa7c51d8f89ac8aa2163420b54e7f0509bdf1806f96e): crafted sweep tx=(*wire.MsgTx)(0xc00281a140)({
 Version: (int32) 2,
 TxIn: ([]*wire.TxIn) (len=1 cap=15) {
  (*wire.TxIn)(0xc000f9e000)({
   PreviousOutPoint: (wire.OutPoint) e730488549fc7990f0e7ab72a7d8f2daefb6b89a97c5f77d673d1c1fbd5b3525:4,
   SignatureScript: ([]uint8) <nil>,
   Witness: (wire.TxWitness) (len=3 cap=3) {
    ([]uint8) (len=71 cap=144) {
     00000000  30 44 02 20 55 ec ba 0f  b8 5a 4e 33 b6 c8 d6 25  |0D. U....ZN3...%|
     00000010  ef e5 b5 68 98 44 16 64  a5 61 02 5e 2b 36 6d 88  |...h.D.d.a.^+6m.|
     00000020  2c 81 1a 0b 02 20 40 9b  98 54 49 24 10 d1 e6 e7  |,.... @..TI$....|
     00000030  8a 5c e7 e6 db a7 21 ed  dd 8f 72 af aa 8c 91 3c  |.\....!...r....<|
     00000040  09 2c 33 dc 1a 9e 01                              |.,3....|
    },
    ([]uint8) (len=32 cap=32) {
     00000000  a2 9c 20 88 66 55 1e d2  62 d9 6b 6a 0c 66 48 b9  |.. .fU..b.kj.fH.|
     00000010  41 cd ca 39 a3 21 f2 ac  42 60 89 ae e0 95 03 c3  |A..9.!..B`......|
    },
    ([]uint8) (len=133 cap=133) {
     00000000  76 a9 14 57 2a 91 d9 50  3e 3e f0 11 a4 e5 ec 94  |v..W*..P>>......|
     00000010  9f 57 35 d2 ac db e1 87  63 ac 67 21 03 19 a9 c4  |.W5.....c.g!....|
     00000020  7e 18 64 79 be c4 03 27  ef cd fc 63 91 ce f3 e2  |~.dy...'...c....|
     00000030  05 0e 26 7f 45 29 00 d5  63 83 aa b4 a6 7c 82 01  |..&.E)..c....|..|
     00000040  20 87 64 75 52 7c 21 03  5c 47 50 35 11 d1 17 30  | .duR|!.\GP5...0|
     00000050  a6 14 c3 7b 4c 46 2b a4  b3 03 3c 67 cd f9 09 4a  |...{LF+...<g...J|
     00000060  6e 0c 60 32 aa a9 ab f8  52 ae 67 a9 14 54 09 d5  |n.`2....R.g..T..|
     00000070  9c 8a c1 bf 9b be 05 04  73 a9 1d 6c f3 8e a3 4c  |........s..l...L|
     00000080  c8 88 ac 68 68                                    |...hh|
    }
   },
   Sequence: (uint32) 0
  })
 },
 TxOut: ([]*wire.TxOut) (len=1 cap=15) {
  (*wire.TxOut)(0xc0005a0040)({
   Value: (int64) 339998,
   PkScript: ([]uint8) (len=22 cap=500) {
    00000000  00 14 94 f2 93 58 b4 b8  e5 6b 14 08 30 79 ab ca  |.....X...k..0y..|
    00000010  c0 66 04 d8 2b 46                                 |.f..+F|
   }
  })
 },
 LockTime: (uint32) 0
})

2019-01-30 02:12:23.906 [INF] NTFN: Dispatching 1 confirmation notification for txid=15ea01435c9d6fc9433d581254c507e74a89a7b6c9572f048011996a94724517
2019-01-30 02:12:23.991 [INF] NTFN: Dispatching 1 confirmation notification for txid=57addab6ccb2a6a1390367e02a1219f1a372e57295971193685459f4931af919
2019-01-30 02:12:23.991 [INF] LNWL: Inserting unconfirmed transaction 14873fbd31df4267edc7187714d863582fb270eccfd1f1d53a4199fc92f5070e
2019-01-30 02:12:24.005 [INF] NTFN: New spend subscription: spend_id=6, outpoint=57addab6ccb2a6a1390367e02a1219f1a372e57295971193685459f4931af919:0, height_hint=560050
2019-01-30 02:12:24.005 [INF] CNCT: *contractcourt.commitSweepResolver(e07afe293b20910363ad5b01bd7f0192f6bf88d385002e74ff8594bf29c4d888:1): waiting for commit output to be swept
2019-01-30 02:12:24.014 [INF] DISC: Authenticated Gossiper is starting
2019-01-30 02:12:24.014 [INF] BRAR: Starting contract observer, watching for breaches.
2019-01-30 02:12:24.015 [INF] NTFN: New block epoch subscription
2019-01-30 02:12:24.047 [INF] CRTR: FilteredChainView starting
2019-01-30 02:12:24.097 [INF] NTFN: New confirmation subscription: txid=14873fbd31df4267edc7187714d863582fb270eccfd1f1d53a4199fc92f5070e, num_confs=1
2019-01-30 02:12:24.100 [INF] NTFN: Dispatching 1 confirmation notification for txid=7a03fe4870bfb51dfec7a9ff311294d0d233c32feb9e6917ca559f503b2666bc
2019-01-30 02:12:24.100 [INF] NTFN: New spend subscription: spend_id=7, outpoint=7a03fe4870bfb51dfec7a9ff311294d0d233c32feb9e6917ca559f503b2666bc:1, height_hint=560200
2019-01-30 02:12:24.101 [INF] NTFN: New spend subscription: spend_id=5, outpoint=15ea01435c9d6fc9433d581254c507e74a89a7b6c9572f048011996a94724517:0, height_hint=560138
2019-01-30 02:12:24.102 [INF] CNCT: *contractcourt.commitSweepResolver(5dfc4e79307094c0ce821d2c67bc89f0bb9e12d47546fa69218196bc6beb3f21:1): waiting for commit output to be swept
2019-01-30 02:12:24.189 [INF] NTFN: Dispatching 1 confirmation notification for txid=5e2d590fcc48098ff6fe0dee6d6a2f624190fc80f0fd7964396c4e08c2526bf1
2019-01-30 02:12:24.226 [INF] CRTR: Filtering chain using 22545 channels active
2019-01-30 02:12:24.228 [INF] CRTR: Prune tip for Channel Graph: height=560705, hash=0000000000000000000d9dda46cd0fa5e8560570087a8a24e20d019e47202678
2019-01-30 02:12:24.289 [INF] NTFN: Dispatching 1 confirmation notification for txid=e05b05e86a6d192645fa01365ef503b360d807d78575f0391e0d4aae326ea9af
2019-01-30 02:12:24.289 [INF] CNCT: *contractcourt.htlcSuccessResolver(55932bb2f35fd5457cb1fa7c51d8f89ac8aa2163420b54e7f0509bdf1806f96e): waiting for sweep tx (txid=14873fbd31df4267edc7187714d863582fb270eccfd1f1d53a4199fc92f5070e) to be confirmed
2019-01-30 02:12:24.378 [INF] CMGR: Server listening on [::]:9735
2019-01-30 02:12:24.378 [INF] SRVR: New inbound connection from 167.99.50.31:56274
2019-01-30 02:12:24.378 [INF] SRVR: Finalizing connection to 02ad6fb8d693dc1e4569bcedefadf5f72a931ae027dc0f0c544b34c1c6f3b9a02b, inbound=true
2019-01-30 02:12:24.379 [INF] SRVR: Pruning peer 02ad6fb8d693dc1e4569bcedefadf5f72a931ae027dc0f0c544b34c1c6f3b9a02b from persistent connections, number of open channels is now zero
2019-01-30 02:12:24.379 [INF] SRVR: New inbound connection from 213.174.156.86:47215
2019-01-30 02:12:24.379 [INF] SRVR: Finalizing connection to 0311cad0edf4ac67298805cf4407d94358ca60cd44f2e360856f3b1c088bcd4782, inbound=true
2019-01-30 02:12:24.380 [INF] SRVR: Pruning peer 0311cad0edf4ac67298805cf4407d94358ca60cd44f2e360856f3b1c088bcd4782 from persistent connections, number of open channels is now zero
2019-01-30 02:12:24.380 [INF] SRVR: Negotiated chan series queries with 02ad6fb8d693dc1e4569bcedefadf5f72a931ae027dc0f0c544b34c1c6f3b9a02b
2019-01-30 02:12:24.380 [INF] DISC: Creating new gossipSyncer for peer=02ad6fb8d693dc1e4569bcedefadf5f72a931ae027dc0f0c544b34c1c6f3b9a02b
2019-01-30 02:12:24.381 [INF] SRVR: Negotiated chan series queries with 0311cad0edf4ac67298805cf4407d94358ca60cd44f2e360856f3b1c088bcd4782
2019-01-30 02:12:24.381 [INF] DISC: Creating new gossipSyncer for peer=0311cad0edf4ac67298805cf4407d94358ca60cd44f2e360856f3b1c088bcd4782
2019-01-30 02:12:24.381 [INF] DISC: gossipSyncer(02ad6fb8d693dc1e4569bcedefadf5f72a931ae027dc0f0c544b34c1c6f3b9a02b): requesting new chans from height=560556 and 4294406739 blocks after
2019-01-30 02:12:24.381 [INF] DISC: gossipSyncer(0311cad0edf4ac67298805cf4407d94358ca60cd44f2e360856f3b1c088bcd4782): requesting new chans from height=560556 and 4294406739 blocks after
2019-01-30 02:12:24.390 [INF] SRVR: New inbound connection from 104.62.47.181:47302
2019-01-30 02:12:24.390 [INF] SRVR: Finalizing connection to 03321fab5e3db6c378e23e9cceb522325dc4f6b0c68819944569128d34cba9cca3, inbound=true
2019-01-30 02:12:24.390 [INF] SRVR: Pruning peer 03321fab5e3db6c378e23e9cceb522325dc4f6b0c68819944569128d34cba9cca3 from persistent connections, number of open channels is now zero
2019-01-30 02:12:24.390 [INF] SRVR: Negotiated chan series queries with 03321fab5e3db6c378e23e9cceb522325dc4f6b0c68819944569128d34cba9cca3
2019-01-30 02:12:24.390 [INF] DISC: Creating new gossipSyncer for peer=03321fab5e3db6c378e23e9cceb522325dc4f6b0c68819944569128d34cba9cca3
2019-01-30 02:12:24.390 [INF] DISC: gossipSyncer(03321fab5e3db6c378e23e9cceb522325dc4f6b0c68819944569128d34cba9cca3): requesting new chans from height=560556 and 4294406739 blocks after
2019-01-30 02:12:24.391 [ERR] PEER: resend failed: no chan sync message stored for channel d41f721369afd68098cc1d6e6cf88475f47284a89400b36985ba14ee44b82975
2019-01-30 02:12:24.391 [INF] DISC: gossipSyncer(0311cad0edf4ac67298805cf4407d94358ca60cd44f2e360856f3b1c088bcd4782): filtering chan range: start_height=560556, num_blocks=4294406739
2019-01-30 02:12:24.391 [INF] DISC: gossipSyncer(0311cad0edf4ac67298805cf4407d94358ca60cd44f2e360856f3b1c088bcd4782): sending final chan range chunk, size=523
2019-01-30 02:12:24.391 [INF] DISC: gossipSyncer(0311cad0edf4ac67298805cf4407d94358ca60cd44f2e360856f3b1c088bcd4782): buffering chan range reply of size=523
2019-01-30 02:12:24.391 [INF] DISC: gossipSyncer(0311cad0edf4ac67298805cf4407d94358ca60cd44f2e360856f3b1c088bcd4782): filtering through 523 chans
2019-01-30 02:12:24.392 [INF] DISC: gossipSyncer(0311cad0edf4ac67298805cf4407d94358ca60cd44f2e360856f3b1c088bcd4782): remote peer has no new chans
2019-01-30 02:12:24.392 [INF] DISC: gossipSyncer(0311cad0edf4ac67298805cf4407d94358ca60cd44f2e360856f3b1c088bcd4782): applying gossipFilter(start=2019-01-30 01:12:24.39204484 +0000 UTC m=-3579.329523424)
2019-01-30 02:12:24.421 [INF] DISC: gossipSyncer(02ad6fb8d693dc1e4569bcedefadf5f72a931ae027dc0f0c544b34c1c6f3b9a02b): filtering chan range: start_height=560556, num_blocks=4294406739
2019-01-30 02:12:24.421 [INF] DISC: gossipSyncer(02ad6fb8d693dc1e4569bcedefadf5f72a931ae027dc0f0c544b34c1c6f3b9a02b): sending final chan range chunk, size=523
2019-01-30 02:12:24.422 [ERR] PEER: resend failed: no chan sync message stored for channel da04228026d0fe8f7292a1027b76d98645bbb3565dd10f3a82a1d69822a9d5c7
2019-01-30 02:12:24.422 [INF] DISC: gossipSyncer(02ad6fb8d693dc1e4569bcedefadf5f72a931ae027dc0f0c544b34c1c6f3b9a02b): buffering chan range reply of size=523
2019-01-30 02:12:24.422 [INF] DISC: gossipSyncer(02ad6fb8d693dc1e4569bcedefadf5f72a931ae027dc0f0c544b34c1c6f3b9a02b): filtering through 523 chans
2019-01-30 02:12:24.423 [INF] DISC: gossipSyncer(02ad6fb8d693dc1e4569bcedefadf5f72a931ae027dc0f0c544b34c1c6f3b9a02b): remote peer has no new chans
2019-01-30 02:12:24.423 [INF] DISC: gossipSyncer(02ad6fb8d693dc1e4569bcedefadf5f72a931ae027dc0f0c544b34c1c6f3b9a02b): applying gossipFilter(start=2019-01-30 01:12:24.423362841 +0000 UTC m=-3579.298205323)
2019-01-30 02:12:24.432 [INF] DISC: gossipSyncer(0311cad0edf4ac67298805cf4407d94358ca60cd44f2e360856f3b1c088bcd4782): applying new update horizon: start=2019-01-30 01:12:24 +0000 UTC, end=2155-03-08 07:40:39 +0000 UTC, backlog_size=6174
2019-01-30 02:12:24.447 [INF] DISC: gossipSyncer(03321fab5e3db6c378e23e9cceb522325dc4f6b0c68819944569128d34cba9cca3): filtering chan range: start_height=560556, num_blocks=4294406739
2019-01-30 02:12:24.447 [INF] DISC: gossipSyncer(03321fab5e3db6c378e23e9cceb522325dc4f6b0c68819944569128d34cba9cca3): sending final chan range chunk, size=523
2019-01-30 02:12:24.447 [INF] DISC: gossipSyncer(03321fab5e3db6c378e23e9cceb522325dc4f6b0c68819944569128d34cba9cca3): buffering chan range reply of size=523
2019-01-30 02:12:24.447 [INF] DISC: gossipSyncer(03321fab5e3db6c378e23e9cceb522325dc4f6b0c68819944569128d34cba9cca3): filtering through 523 chans
2019-01-30 02:12:24.448 [INF] DISC: gossipSyncer(03321fab5e3db6c378e23e9cceb522325dc4f6b0c68819944569128d34cba9cca3): remote peer has no new chans
2019-01-30 02:12:24.448 [INF] DISC: gossipSyncer(03321fab5e3db6c378e23e9cceb522325dc4f6b0c68819944569128d34cba9cca3): applying gossipFilter(start=2019-01-30 01:12:24.448112232 +0000 UTC m=-3579.273455932)
2019-01-30 02:12:24.488 [INF] CNCT: *contractcourt.commitSweepResolver(4a1d62d72c8848c58fb90f5235670436489b21aa22774789288f79e6a2b1c3aa:1): waiting for commit output to be swept
2019-01-30 02:12:24.550 [INF] DISC: gossipSyncer(02ad6fb8d693dc1e4569bcedefadf5f72a931ae027dc0f0c544b34c1c6f3b9a02b): applying new update horizon: start=2019-01-30 01:12:24 +0000 UTC, end=2155-03-08 07:40:39 +0000 UTC, backlog_size=6174
2019-01-30 02:12:24.579 [INF] SRVR: Initializing peer network bootstrappers!
2019-01-30 02:12:24.579 [INF] SRVR: Creating DNS peer bootstrapper with seeds: [[nodes.lightning.directory soa.nodes.lightning.directory]]
2019-01-30 02:12:24.586 [INF] SRVR: New inbound connection from 138.68.14.104:44234
2019-01-30 02:12:24.586 [INF] SRVR: Finalizing connection to 03bb88ccc444534da7b5b64b4f7b15e1eccb18e102db0e400d4b9cfe93763aa26d, inbound=true
2019-01-30 02:12:24.587 [INF] SRVR: Pruning peer 03bb88ccc444534da7b5b64b4f7b15e1eccb18e102db0e400d4b9cfe93763aa26d from persistent connections, number of open channels is now zero
2019-01-30 02:12:24.606 [INF] DISC: gossipSyncer(03321fab5e3db6c378e23e9cceb522325dc4f6b0c68819944569128d34cba9cca3): applying new update horizon: start=2019-01-30 01:12:24 +0000 UTC, end=2155-03-08 07:40:39 +0000 UTC, backlog_size=6174
2019-01-30 02:12:24.630 [INF] SRVR: Negotiated chan series queries with 03bb88ccc444534da7b5b64b4f7b15e1eccb18e102db0e400d4b9cfe93763aa26d
2019-01-30 02:12:24.630 [INF] DISC: Creating new gossipSyncer for peer=03bb88ccc444534da7b5b64b4f7b15e1eccb18e102db0e400d4b9cfe93763aa26d
2019-01-30 02:12:24.639 [INF] DISC: gossipSyncer(03bb88ccc444534da7b5b64b4f7b15e1eccb18e102db0e400d4b9cfe93763aa26d): requesting new chans from height=560556 and 4294406739 blocks after
2019-01-30 02:12:24.665 [INF] DISC: gossipSyncer(03bb88ccc444534da7b5b64b4f7b15e1eccb18e102db0e400d4b9cfe93763aa26d): filtering chan range: start_height=560556, num_blocks=4294406739
2019-01-30 02:12:24.665 [INF] DISC: gossipSyncer(03bb88ccc444534da7b5b64b4f7b15e1eccb18e102db0e400d4b9cfe93763aa26d): sending final chan range chunk, size=523
2019-01-30 02:12:24.665 [ERR] PEER: resend failed: no chan sync message stored for channel 7ea14f456463e66be90dbf80677fc8e51923adc14ae66efa7e2c13613ae9e7a5
2019-01-30 02:12:24.677 [INF] NTFN: Dispatching 1 confirmation notification for txid=e0eb8dbca98a908d73f8f269bf53c0b67cb0eb09f76110de44f6b349352a1238
2019-01-30 02:12:24.705 [INF] DISC: gossipSyncer(03bb88ccc444534da7b5b64b4f7b15e1eccb18e102db0e400d4b9cfe93763aa26d): buffering chan range reply of size=522
2019-01-30 02:12:24.705 [INF] DISC: gossipSyncer(03bb88ccc444534da7b5b64b4f7b15e1eccb18e102db0e400d4b9cfe93763aa26d): filtering through 522 chans
2019-01-30 02:12:24.705 [INF] DISC: gossipSyncer(03bb88ccc444534da7b5b64b4f7b15e1eccb18e102db0e400d4b9cfe93763aa26d): remote peer has no new chans
2019-01-30 02:12:24.705 [INF] DISC: gossipSyncer(03bb88ccc444534da7b5b64b4f7b15e1eccb18e102db0e400d4b9cfe93763aa26d): applying gossipFilter(start=2019-01-30 01:12:24.705733966 +0000 UTC m=-3579.015834198)
2019-01-30 02:12:24.734 [INF] DISC: gossipSyncer(03bb88ccc444534da7b5b64b4f7b15e1eccb18e102db0e400d4b9cfe93763aa26d): fetching chan anns for 1 chans
2019-01-30 02:12:24.737 [INF] SRVR: New inbound connection from 137.226.34.46:59268
2019-01-30 02:12:24.737 [INF] SRVR: Finalizing connection to 027ce055380348d7812d2ae7745701c9f93e70c1adeb2657f053f91df4f2843c71, inbound=true
2019-01-30 02:12:24.738 [INF] SRVR: Pruning peer 027ce055380348d7812d2ae7745701c9f93e70c1adeb2657f053f91df4f2843c71 from persistent connections, number of open channels is now zero
2019-01-30 02:12:24.738 [INF] SRVR: Negotiated chan series queries with 027ce055380348d7812d2ae7745701c9f93e70c1adeb2657f053f91df4f2843c71
2019-01-30 02:12:24.738 [INF] DISC: Creating new gossipSyncer for peer=027ce055380348d7812d2ae7745701c9f93e70c1adeb2657f053f91df4f2843c71
2019-01-30 02:12:24.738 [INF] DISC: gossipSyncer(027ce055380348d7812d2ae7745701c9f93e70c1adeb2657f053f91df4f2843c71): requesting new chans from height=560556 and 4294406739 blocks after
2019-01-30 02:12:24.795 [INF] NTFN: Dispatching 1 confirmation notification for txid=bcec52500748200ed0848ddfad1e9ed30f7ae1c552c528bbd9da69d52a291f59
2019-01-30 02:12:24.795 [INF] NTFN: New spend subscription: spend_id=8, outpoint=5e2d590fcc48098ff6fe0dee6d6a2f624190fc80f0fd7964396c4e08c2526bf1:0, height_hint=527519
2019-01-30 02:12:24.795 [INF] CNCT: *contractcourt.commitSweepResolver(883f4b2cc4629d495bff2accca14d389b6e76e5174cb7ffe6fc3fd3f3ff4f111:0): waiting for commit output to be swept
2019-01-30 02:12:24.795 [INF] NTFN: New spend subscription: spend_id=11, outpoint=bcec52500748200ed0848ddfad1e9ed30f7ae1c552c528bbd9da69d52a291f59:0, height_hint=542527
2019-01-30 02:12:24.795 [INF] CNCT: *contractcourt.commitSweepResolver(9cebba83a510e9b2d52bbaeb9986b9e57ba86ff7adec1310c6afda253334a408:0): waiting for commit output to be swept
2019-01-30 02:12:24.845 [INF] DISC: gossipSyncer(027ce055380348d7812d2ae7745701c9f93e70c1adeb2657f053f91df4f2843c71): filtering chan range: start_height=560556, num_blocks=4294406739
2019-01-30 02:12:24.845 [INF] DISC: gossipSyncer(027ce055380348d7812d2ae7745701c9f93e70c1adeb2657f053f91df4f2843c71): sending final chan range chunk, size=523
2019-01-30 02:12:24.845 [INF] DISC: gossipSyncer(027ce055380348d7812d2ae7745701c9f93e70c1adeb2657f053f91df4f2843c71): buffering chan range reply of size=523
2019-01-30 02:12:24.845 [INF] DISC: gossipSyncer(027ce055380348d7812d2ae7745701c9f93e70c1adeb2657f053f91df4f2843c71): filtering through 523 chans
2019-01-30 02:12:24.846 [INF] DISC: gossipSyncer(027ce055380348d7812d2ae7745701c9f93e70c1adeb2657f053f91df4f2843c71): remote peer has no new chans
2019-01-30 02:12:24.846 [INF] DISC: gossipSyncer(027ce055380348d7812d2ae7745701c9f93e70c1adeb2657f053f91df4f2843c71): applying gossipFilter(start=2019-01-30 01:12:24.846484064 +0000 UTC m=-3578.875084200)
2019-01-30 02:12:24.878 [INF] DISC: gossipSyncer(03bb88ccc444534da7b5b64b4f7b15e1eccb18e102db0e400d4b9cfe93763aa26d): applying new update horizon: start=2019-01-30 01:12:24 +0000 UTC, end=2155-03-08 07:40:39 +0000 UTC, backlog_size=6174
2019-01-30 02:12:24.918 [INF] NTFN: Dispatching 1 confirmation notification for txid=3b4d9999553ac56561fb49a38d8adf327cf0051f210150edde7e0f36111a1ae4
2019-01-30 02:12:24.918 [INF] NTFN: New spend subscription: spend_id=9, outpoint=e05b05e86a6d192645fa01365ef503b360d807d78575f0391e0d4aae326ea9af:1, height_hint=560135
2019-01-30 02:12:24.918 [INF] NTFN: New spend subscription: spend_id=12, outpoint=3b4d9999553ac56561fb49a38d8adf327cf0051f210150edde7e0f36111a1ae4:0, height_hint=560200
2019-01-30 02:12:24.918 [INF] NTFN: New spend subscription: spend_id=10, outpoint=e0eb8dbca98a908d73f8f269bf53c0b67cb0eb09f76110de44f6b349352a1238:0, height_hint=560698
2019-01-30 02:12:24.983 [INF] DISC: gossipSyncer(027ce055380348d7812d2ae7745701c9f93e70c1adeb2657f053f91df4f2843c71): applying new update horizon: start=2019-01-30 01:12:23 +0000 UTC, end=2155-03-08 07:40:38 +0000 UTC, backlog_size=6174
2019-01-30 02:12:25.452 [INF] SRVR: New inbound connection from 139.216.109.30:33798
2019-01-30 02:12:25.452 [INF] SRVR: Finalizing connection to 025bc44f4a09acfb3c69081d97a3deb88816b5a934287c9f7cc40648213611c373, inbound=true
2019-01-30 02:12:25.453 [INF] SRVR: Pruning peer 025bc44f4a09acfb3c69081d97a3deb88816b5a934287c9f7cc40648213611c373 from persistent connections, number of open channels is now zero
2019-01-30 02:12:25.453 [INF] SRVR: Negotiated chan series queries with 025bc44f4a09acfb3c69081d97a3deb88816b5a934287c9f7cc40648213611c373
2019-01-30 02:12:25.453 [INF] DISC: Creating new gossipSyncer for peer=025bc44f4a09acfb3c69081d97a3deb88816b5a934287c9f7cc40648213611c373
2019-01-30 02:12:25.454 [INF] DISC: gossipSyncer(025bc44f4a09acfb3c69081d97a3deb88816b5a934287c9f7cc40648213611c373): requesting new chans from height=560556 and 4294406739 blocks after
2019-01-30 02:12:25.771 [INF] DISC: gossipSyncer(025bc44f4a09acfb3c69081d97a3deb88816b5a934287c9f7cc40648213611c373): filtering chan range: start_height=560556, num_blocks=4294406739
2019-01-30 02:12:25.771 [INF] DISC: gossipSyncer(025bc44f4a09acfb3c69081d97a3deb88816b5a934287c9f7cc40648213611c373): sending final chan range chunk, size=523
2019-01-30 02:12:25.779 [INF] DISC: gossipSyncer(025bc44f4a09acfb3c69081d97a3deb88816b5a934287c9f7cc40648213611c373): buffering chan range reply of size=523
2019-01-30 02:12:25.779 [INF] DISC: gossipSyncer(025bc44f4a09acfb3c69081d97a3deb88816b5a934287c9f7cc40648213611c373): filtering through 523 chans
2019-01-30 02:12:25.780 [INF] DISC: gossipSyncer(025bc44f4a09acfb3c69081d97a3deb88816b5a934287c9f7cc40648213611c373): remote peer has no new chans
2019-01-30 02:12:25.780 [INF] DISC: gossipSyncer(025bc44f4a09acfb3c69081d97a3deb88816b5a934287c9f7cc40648213611c373): applying gossipFilter(start=2019-01-30 01:12:25.780189806 +0000 UTC m=-3577.941378458)
2019-01-30 02:12:26.041 [INF] DISC: gossipSyncer(025bc44f4a09acfb3c69081d97a3deb88816b5a934287c9f7cc40648213611c373): applying new update horizon: start=2019-01-30 01:12:25 +0000 UTC, end=2155-03-08 07:40:40 +0000 UTC, backlog_size=6174
2019-01-30 02:12:27.167 [INF] CNCT: *contractcourt.commitSweepResolver(e612b571044b5386d1c15babd701823ea164ab045a8a189552ea6739540c8d1b:1): waiting for commit output to be swept

Expected behaviour

Channels should close and sweep into wallet

Actual behaviour

Funds stuck in limbo

Roasbeef commented 5 years ago

For channels that have a very small amount lingering like:

        {
            "channel": {
                "remote_node_pub": "03a96577e4cf8cac96937f4bf2753f7bd71323af5563690c8ed39c4e058c66c6c7",
                "channel_point": "5dfc4e79307094c0ce821d2c67bc89f0bb9e12d47546fa69218196bc6beb3f21:1",
                "capacity": "50000",
                "local_balance": "579",
                "remote_balance": "0"
            },
            "closing_txid": "15ea01435c9d6fc9433d581254c507e74a89a7b6c9572f048011996a94724517",
            "limbo_balance": "579",
            "maturity_height": 560282,
            "blocks_til_maturity": -423,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        },

We won't yet sweep those since we'll likely pay more in fees that we'll get from the output. This will change in the future though, in order to promote the wallet having a small UTXO footprint.

Many of those other channels for example:

        {
            "channel": {
                "remote_node_pub": "02c12b5459cf107ee0440cae41902f1189db50fa003a077f3a6fbe6b5760218695",
                "channel_point": "39389828ccded50ad1d380ee0fc59c9f9fa7224f4fe6bfe2c58c6772592b34c8:1",
                "capacity": "16777215",
                "local_balance": "226977",
                "remote_balance": "0"
            },
            "closing_txid": "3b4d9999553ac56561fb49a38d8adf327cf0051f210150edde7e0f36111a1ae4",
            "limbo_balance": "226977",
            "maturity_height": 562216,
            "blocks_til_maturity": 1511,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]

Haven't yet had their timelocks expire.

The final case in your report seems to be channels that have been closed with no coins on our side, but which are still showing up in pendingchannels (shows zero balance at time of close). Are you running a node with a txindex, and also can you provide logs with those txid's

Roasbeef commented 5 years ago

I rescanned the wallet over the last several hours,

There's no need to rescan, the funds are timelocked if they needed to be force closed.

Horndev commented 5 years ago

I had to rescan because the wallet sendcoins was giving me a utxo already spent error. rescan fixed that.

yes - txindex is on

I know that there are some channels I'm waiting to mature - it's the ones with negative blocks to maturity which are concerning, which should be able to all be swept up. In fact - you can see in the logs that lnd is trying to sweep but the transaction doesn't seem to take.

I will have to get the logs from bitcoind later tonight.

Thanks a lot for the help!

ghost commented 5 years ago

I have this issue too; I see "blocks_til_maturity": -1..

{
    "channel": {
        "remote_node_pub": "0312c02755c6a3475f872be27e71fdb7703a61a25777401a26125e1c772c7e0f6a",
        "channel_point": "28b9441399c7962fae9a7ef323456d5dfc0f08b2ea4eba319c084cf9779a9162:1",
        "capacity": "1200000",
        "local_balance": "239544",
        "remote_balance": "0"
    },
    "closing_txid": "99a7a7b340b5d6334f7695185f916eb0d46d6be0be603a741f6ea98e467062be",
    "limbo_balance": "958454",
    "maturity_height": 0,
    "blocks_til_maturity": 0,
    "recovered_balance": "0",
    "pending_htlcs": [
        {
            "incoming": false,
            "amount": "958454",
            "outpoint": "99a7a7b340b5d6334f7695185f916eb0d46d6be0be603a741f6ea98e467062be:2",
            "maturity_height": 560774,
            "blocks_til_maturity": -1,
            "stage": 2
        }
    ]
}

In the eyes of the public, the channel is closed: https://1ml.com/channel/616504965900992513 Yet I haven't gotten the funds back as far as I can tell.

After another restart of lnd, I saw this in the log:

[ERR] NTFN: Rescan to determine the spend details of 99a7a7b340b5d6334f7695185f916eb0d46d6be0be603a741f6ea98e467062be:2 failed: transaction not found within range

I also see this, not sure if it's related:

[ERR] LNWL: Unable to receive ZMQ rawtx message: expected message frame
[ERR] LNWL: Unable to receive ZMQ rawtx message: invalid flag
[ERR] LNWL: Unable to receive ZMQ rawtx message: invalid flag
[ERR] LNWL: Unable to receive ZMQ rawtx message: invalid flag
[ERR] LNWL: Unable to receive ZMQ rawtx message: frame too large
[ERR] LNWL: Unable to receive ZMQ rawtx message: invalid flag
[ERR] LNWL: Unable to receive ZMQ rawtx message: invalid flag
[ERR] LNWL: Unable to receive ZMQ rawtx message: invalid flag
[ERR] LNWL: Unable to receive ZMQ rawtx message: invalid flag
[ERR] LNWL: Unable to receive ZMQ rawtx message: invalid flag
[ERR] LNWL: Unable to receive ZMQ rawtx message: invalid flag
[ERR] LNWL: Unable to receive ZMQ rawtx message: invalid flag
[ERR] LNWL: Unable to receive ZMQ rawtx message: invalid flag
[ERR] LNWL: Unable to receive ZMQ rawtx message: frame too large
[ERR] LNWL: Unable to receive ZMQ rawtx message: invalid flag
[ERR] LNWL: Unable to receive ZMQ rawtx message: invalid flag
[ERR] LNWL: Unable to receive ZMQ rawtx message: invalid flag
[ERR] LNWL: Unable to receive ZMQ rawtx message: invalid flag
[ERR] LNWL: Unable to receive ZMQ rawtx message: invalid flag
[ERR] LNWL: Unable to receive ZMQ rawtx message: invalid flag
[ERR] LNWL: Unable to receive ZMQ rawtx message: invalid flag
Horndev commented 5 years ago

Ok, here is my bitcoind log on startup with debug=1

2019-01-31 03:17:38 Received a POST request for / from 127.0.0.1:49502
2019-01-31 03:17:38 ThreadRPCServer method=getblockhash
2019-01-31 03:17:38 Received a POST request for / from 127.0.0.1:49508
2019-01-31 03:17:38 ThreadRPCServer method=getnetworkinfo
2019-01-31 03:17:39 trying connection 223.204.248.100:8333 lastseen=804.3hrs
2019-01-31 03:17:40 Received a POST request for / from 127.0.0.1:49512
2019-01-31 03:17:40 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:40 Received a POST request for / from 127.0.0.1:49514
2019-01-31 03:17:40 ThreadRPCServer method=getblockheader
2019-01-31 03:17:40 Received a POST request for / from 127.0.0.1:49516
2019-01-31 03:17:40 ThreadRPCServer method=getblockhash
2019-01-31 03:17:40 Received a POST request for / from 127.0.0.1:49518
2019-01-31 03:17:40 ThreadRPCServer method=getblockheader
2019-01-31 03:17:40 Received a POST request for / from 127.0.0.1:49520
2019-01-31 03:17:40 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:41 Received a POST request for / from 127.0.0.1:49528
2019-01-31 03:17:41 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:41 Received a POST request for / from 127.0.0.1:49530
2019-01-31 03:17:41 ThreadRPCServer method=getblockheader
2019-01-31 03:17:41 Received a POST request for / from 127.0.0.1:49532
2019-01-31 03:17:41 ThreadRPCServer method=getblockheader
2019-01-31 03:17:41 Received a POST request for / from 127.0.0.1:49534
2019-01-31 03:17:41 ThreadRPCServer method=getblockhash
2019-01-31 03:17:41 Received a POST request for / from 127.0.0.1:49536
2019-01-31 03:17:41 ThreadRPCServer method=getblock
2019-01-31 03:17:41 Received a POST request for / from 127.0.0.1:49538
2019-01-31 03:17:41 ThreadRPCServer method=getblockhash
2019-01-31 03:17:41 Received a POST request for / from 127.0.0.1:49540
2019-01-31 03:17:41 ThreadRPCServer method=getblock
2019-01-31 03:17:41 Received a POST request for / from 127.0.0.1:49542
2019-01-31 03:17:41 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:41 Received a POST request for / from 127.0.0.1:49544
2019-01-31 03:17:41 ThreadRPCServer method=getblockheader
2019-01-31 03:17:44 connection to 223.204.248.100:8333 timeout
2019-01-31 03:17:44 trying connection 46.219.111.171:8333 lastseen=6479.6hrs
2019-01-31 03:17:45 Received a POST request for / from 127.0.0.1:49554
2019-01-31 03:17:45 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:45 Received a POST request for / from 127.0.0.1:49558
2019-01-31 03:17:45 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:45 Received a POST request for / from 127.0.0.1:49560
2019-01-31 03:17:45 ThreadRPCServer method=getblockheader
2019-01-31 03:17:45 Received a POST request for / from 127.0.0.1:49562
2019-01-31 03:17:45 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:45 Received a POST request for / from 127.0.0.1:49564
2019-01-31 03:17:45 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:45 Received a POST request for / from 127.0.0.1:49566
2019-01-31 03:17:45 ThreadRPCServer method=getblockheader
2019-01-31 03:17:45 Received a POST request for / from 127.0.0.1:49568
2019-01-31 03:17:45 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:45 Received a POST request for / from 127.0.0.1:49570
2019-01-31 03:17:45 ThreadRPCServer method=sendrawtransaction
2019-01-31 03:17:45 Received a POST request for / from 127.0.0.1:49572
2019-01-31 03:17:45 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:45 Received a POST request for / from 127.0.0.1:49574
2019-01-31 03:17:45 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:45 Received a POST request for / from 127.0.0.1:49576
2019-01-31 03:17:45 ThreadRPCServer method=getblockhash
2019-01-31 03:17:45 Received a POST request for / from 127.0.0.1:49578
2019-01-31 03:17:45 ThreadRPCServer method=getblockheader
2019-01-31 03:17:45 Received a POST request for / from 127.0.0.1:49580
2019-01-31 03:17:45 ThreadRPCServer method=gettxout
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49582
2019-01-31 03:17:46 ThreadRPCServer method=estimatesmartfee
2019-01-31 03:17:46 FeeEst: 3 >60% decay 0.96200: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 1.0/(1.0 0 mem 0.0 out)
2019-01-31 03:17:46 FeeEst: 6 >85% decay 0.96200: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 1.0/(1.0 0 mem 0.0 out)
2019-01-31 03:17:46 FeeEst: 12 >95% decay 0.96200: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 1.0/(1.0 0 mem 0.0 out)
2019-01-31 03:17:46 FeeEst: 12 >95% decay 0.99520: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 8.5/(8.5 0 mem 0.0 out)
2019-01-31 03:17:46 FeeEst: 12 >95% decay 0.99931: feerate: 10703.7 from (2925.26 - 1e+99) 99.26% 147.1/(148.2 0 mem 0.0 out) Fail: (0 - 2925.26) 98.33% 37.9/(38.5 0 mem 0.0 out)
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49584
2019-01-31 03:17:46 ThreadRPCServer method=gettxout
2019-01-31 03:17:46 leveldb: Compacting 1@1 + 2@2 files
2019-01-31 03:17:46 leveldb: Generated table #640994@1: 41838 keys, 2173748 bytes
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49586
2019-01-31 03:17:46 ThreadRPCServer method=estimatesmartfee
2019-01-31 03:17:46 FeeEst: 3 >60% decay 0.96200: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 1.0/(1.0 0 mem 0.0 out)
2019-01-31 03:17:46 FeeEst: 6 >85% decay 0.96200: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 1.0/(1.0 0 mem 0.0 out)
2019-01-31 03:17:46 FeeEst: 12 >95% decay 0.96200: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 1.0/(1.0 0 mem 0.0 out)
2019-01-31 03:17:46 FeeEst: 12 >95% decay 0.99520: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 8.5/(8.5 0 mem 0.0 out)
2019-01-31 03:17:46 FeeEst: 12 >95% decay 0.99931: feerate: 10703.7 from (2925.26 - 1e+99) 99.26% 147.1/(148.2 0 mem 0.0 out) Fail: (0 - 2925.26) 98.33% 37.9/(38.5 0 mem 0.0 out)
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49588
2019-01-31 03:17:46 ThreadRPCServer method=gettxout
2019-01-31 03:17:46 leveldb: Generated table #640995@1: 42528 keys, 2177694 bytes
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49590
2019-01-31 03:17:46 ThreadRPCServer method=estimatesmartfee
2019-01-31 03:17:46 FeeEst: 3 >60% decay 0.96200: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 1.0/(1.0 0 mem 0.0 out)
2019-01-31 03:17:46 FeeEst: 6 >85% decay 0.96200: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 1.0/(1.0 0 mem 0.0 out)
2019-01-31 03:17:46 FeeEst: 12 >95% decay 0.96200: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 1.0/(1.0 0 mem 0.0 out)
2019-01-31 03:17:46 FeeEst: 12 >95% decay 0.99520: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 8.5/(8.5 0 mem 0.0 out)
2019-01-31 03:17:46 FeeEst: 12 >95% decay 0.99931: feerate: 10703.7 from (2925.26 - 1e+99) 99.26% 147.1/(148.2 0 mem 0.0 out) Fail: (0 - 2925.26) 98.33% 37.9/(38.5 0 mem 0.0 out)
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49592
2019-01-31 03:17:46 ThreadRPCServer method=gettxout
2019-01-31 03:17:46 leveldb: Generated table #640996@1: 39564 keys, 2036117 bytes
2019-01-31 03:17:46 leveldb: Compacted 1@1 + 2@2 files => 6387559 bytes
2019-01-31 03:17:46 leveldb: compacted to: files[ 0 1 17 91 1398 0 0 ]
2019-01-31 03:17:46 leveldb: Delete type=2 #640962
2019-01-31 03:17:46 leveldb: Delete type=2 #640969
2019-01-31 03:17:46 leveldb: Delete type=2 #640949
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49594
2019-01-31 03:17:46 ThreadRPCServer method=estimatesmartfee
2019-01-31 03:17:46 FeeEst: 3 >60% decay 0.96200: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 1.0/(1.0 0 mem 0.0 out)
2019-01-31 03:17:46 FeeEst: 6 >85% decay 0.96200: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 1.0/(1.0 0 mem 0.0 out)
2019-01-31 03:17:46 FeeEst: 12 >95% decay 0.96200: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 1.0/(1.0 0 mem 0.0 out)
2019-01-31 03:17:46 FeeEst: 12 >95% decay 0.99520: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 8.5/(8.5 0 mem 0.0 out)
2019-01-31 03:17:46 FeeEst: 12 >95% decay 0.99931: feerate: 10703.7 from (2925.26 - 1e+99) 99.26% 147.1/(148.2 0 mem 0.0 out) Fail: (0 - 2925.26) 98.33% 37.9/(38.5 0 mem 0.0 out)
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49596
2019-01-31 03:17:46 ThreadRPCServer method=gettxout
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49598
2019-01-31 03:17:46 leveldb: Compacting 1@1 + 3@2 files
2019-01-31 03:17:46 ThreadRPCServer method=getblockhash
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49600
2019-01-31 03:17:46 ThreadRPCServer method=getrawtransaction
2019-01-31 03:17:46 leveldb: Generated table #640997@1: 43656 keys, 2176700 bytes
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49602
2019-01-31 03:17:46 ThreadRPCServer method=getblockheader
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49604
2019-01-31 03:17:46 ThreadRPCServer method=getblockheader
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49606
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49608
2019-01-31 03:17:46 ThreadRPCServer method=estimatesmartfee
2019-01-31 03:17:46 FeeEst: 3 >60% decay 0.96200: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 1.0/(1.0 0 mem 0.0 out)
2019-01-31 03:17:46 ThreadRPCServer method=getblockhash
2019-01-31 03:17:46 FeeEst: 6 >85% decay 0.96200: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 1.0/(1.0 0 mem 0.0 out)
2019-01-31 03:17:46 FeeEst: 12 >95% decay 0.96200: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 1.0/(1.0 0 mem 0.0 out)
2019-01-31 03:17:46 FeeEst: 12 >95% decay 0.99520: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 8.5/(8.5 0 mem 0.0 out)
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49610
2019-01-31 03:17:46 ThreadRPCServer method=getblock
2019-01-31 03:17:46 FeeEst: 12 >95% decay 0.99931: feerate: 10703.7 from (2925.26 - 1e+99) 99.26% 147.1/(148.2 0 mem 0.0 out) Fail: (0 - 2925.26) 98.33% 37.9/(38.5 0 mem 0.0 out)
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49612
2019-01-31 03:17:46 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49614
2019-01-31 03:17:46 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49616
2019-01-31 03:17:46 ThreadRPCServer method=getrawtransaction
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49618
2019-01-31 03:17:46 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49620
2019-01-31 03:17:46 ThreadRPCServer method=getblock
2019-01-31 03:17:46 leveldb: Generated table #640998@1: 42374 keys, 2174217 bytes
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49628
2019-01-31 03:17:46 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49630
2019-01-31 03:17:46 ThreadRPCServer method=getrawtransaction
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49632
2019-01-31 03:17:46 ThreadRPCServer method=getblockhash
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49634
2019-01-31 03:17:46 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49636
2019-01-31 03:17:46 ThreadRPCServer method=getblock
2019-01-31 03:17:46 Received a POST request for / from 127.0.0.1:49638
2019-01-31 03:17:46 ThreadRPCServer method=getblock
2019-01-31 03:17:47 leveldb: Generated table #640999@1: 41968 keys, 2173584 bytes
2019-01-31 03:17:47 Received a POST request for / from 127.0.0.1:49640
2019-01-31 03:17:47 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:47 Received a POST request for / from 127.0.0.1:49644
2019-01-31 03:17:47 Received a POST request for / from 127.0.0.1:49642
2019-01-31 03:17:47 ThreadRPCServer method=estimatesmartfee
2019-01-31 03:17:47 ThreadRPCServer method=getrawtransaction
2019-01-31 03:17:47 FeeEst: 3 >60% decay 0.96200: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 1.0/(1.0 0 mem 0.0 out)
2019-01-31 03:17:47 FeeEst: 6 >85% decay 0.96200: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 1.0/(1.0 0 mem 0.0 out)
2019-01-31 03:17:47 FeeEst: 12 >95% decay 0.96200: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 1.0/(1.0 0 mem 0.0 out)
2019-01-31 03:17:47 FeeEst: 12 >95% decay 0.99520: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 8.5/(8.5 0 mem 0.0 out)
2019-01-31 03:17:47 FeeEst: 12 >95% decay 0.99931: feerate: 10703.7 from (2925.26 - 1e+99) 99.26% 147.1/(148.2 0 mem 0.0 out) Fail: (0 - 2925.26) 98.33% 37.9/(38.5 0 mem 0.0 out)
2019-01-31 03:17:47 Received a POST request for / from 127.0.0.1:49646
2019-01-31 03:17:47 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:47 Received a POST request for / from 127.0.0.1:49648
2019-01-31 03:17:47 ThreadRPCServer method=getblock
2019-01-31 03:17:47 leveldb: Generated table #641000@1: 35211 keys, 1830292 bytes
2019-01-31 03:17:47 leveldb: Compacted 1@1 + 3@2 files => 8354793 bytes
2019-01-31 03:17:47 leveldb: compacted to: files[ 0 0 18 91 1398 0 0 ]
2019-01-31 03:17:47 leveldb: Delete type=2 #640952
2019-01-31 03:17:47 leveldb: Delete type=2 #640964
2019-01-31 03:17:47 leveldb: Delete type=2 #640971
2019-01-31 03:17:47 leveldb: Delete type=2 #640972
2019-01-31 03:17:47 Received a POST request for / from 127.0.0.1:49650
2019-01-31 03:17:47 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:47 Received a POST request for / from 127.0.0.1:49652
2019-01-31 03:17:47 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:47 Received a POST request for / from 127.0.0.1:49654
2019-01-31 03:17:47 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:47 Received a POST request for / from 127.0.0.1:49656
2019-01-31 03:17:47 ThreadRPCServer method=getrawtransaction
2019-01-31 03:17:47 Received a POST request for / from 127.0.0.1:49658
2019-01-31 03:17:47 ThreadRPCServer method=gettxout
2019-01-31 03:17:47 Received a POST request for / from 127.0.0.1:49660
2019-01-31 03:17:47 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:47 Received a POST request for / from 127.0.0.1:49662
2019-01-31 03:17:47 ThreadRPCServer method=getblock
2019-01-31 03:17:47 Received a POST request for / from 127.0.0.1:49664
2019-01-31 03:17:47 ThreadRPCServer method=getrawtransaction
2019-01-31 03:17:47 Received a POST request for / from 127.0.0.1:49666
2019-01-31 03:17:47 ThreadRPCServer method=gettxout
2019-01-31 03:17:47 Received a POST request for / from 127.0.0.1:49668
2019-01-31 03:17:47 ThreadRPCServer method=getrawtransaction
2019-01-31 03:17:47 Received a POST request for / from 127.0.0.1:49670
2019-01-31 03:17:47 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:47 Received a POST request for / from 127.0.0.1:49672
2019-01-31 03:17:47 ThreadRPCServer method=getblock
2019-01-31 03:17:48 Received a POST request for / from 127.0.0.1:49674
2019-01-31 03:17:48 ThreadRPCServer method=getblock
2019-01-31 03:17:48 Received a POST request for / from 127.0.0.1:49676
2019-01-31 03:17:48 ThreadRPCServer method=sendrawtransaction
2019-01-31 03:17:48 leveldb: Compacting 1@2 + 0@3 files
2019-01-31 03:17:48 Received a POST request for / from 127.0.0.1:49678
2019-01-31 03:17:48 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:48 Received a POST request for / from 127.0.0.1:49680
2019-01-31 03:17:48 ThreadRPCServer method=getrawtransaction
2019-01-31 03:17:48 leveldb: Generated table #641001@2: 3452 keys, 178559 bytes
2019-01-31 03:17:48 leveldb: Generated table #641002@2: 3577 keys, 187365 bytes
2019-01-31 03:17:48 leveldb: Generated table #641003@2: 3527 keys, 186625 bytes
2019-01-31 03:17:48 leveldb: Generated table #641004@2: 3714 keys, 191028 bytes
2019-01-31 03:17:48 leveldb: Generated table #641005@2: 3788 keys, 193969 bytes
2019-01-31 03:17:48 leveldb: Generated table #641006@2: 3698 keys, 193278 bytes
2019-01-31 03:17:48 leveldb: Generated table #641007@2: 3667 keys, 191209 bytes
2019-01-31 03:17:48 Received a POST request for / from 127.0.0.1:49682
2019-01-31 03:17:48 ThreadRPCServer method=getrawtransaction
2019-01-31 03:17:48 Received a POST request for / from 127.0.0.1:49684
2019-01-31 03:17:48 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:48 Received a POST request for / from 127.0.0.1:49686
2019-01-31 03:17:48 ThreadRPCServer method=gettxout
2019-01-31 03:17:48 Received a POST request for / from 127.0.0.1:49688
2019-01-31 03:17:48 ThreadRPCServer method=getrawtransaction
2019-01-31 03:17:48 leveldb: Generated table #641008@2: 3860 keys, 200654 bytes
2019-01-31 03:17:48 leveldb: Generated table #641009@2: 3879 keys, 196738 bytes
2019-01-31 03:17:48 leveldb: Generated table #641010@2: 3885 keys, 198592 bytes
2019-01-31 03:17:48 leveldb: Generated table #641011@2: 3782 keys, 198409 bytes
2019-01-31 03:17:48 leveldb: Generated table #641012@2: 1120 keys, 58429 bytes
2019-01-31 03:17:48 leveldb: Compacted 1@2 + 0@3 files => 2174855 bytes
2019-01-31 03:17:48 leveldb: compacted to: files[ 0 0 17 103 1398 0 0 ]
2019-01-31 03:17:48 leveldb: Delete type=2 #640967
2019-01-31 03:17:49 Received a POST request for / from 127.0.0.1:49690
2019-01-31 03:17:49 ThreadRPCServer method=getblock
2019-01-31 03:17:49 Received a POST request for / from 127.0.0.1:49692
2019-01-31 03:17:49 ThreadRPCServer method=getblock
2019-01-31 03:17:49 Received a POST request for / from 127.0.0.1:49694
2019-01-31 03:17:49 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:49 Received a POST request for / from 127.0.0.1:49696
2019-01-31 03:17:49 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:49 Received a POST request for / from 127.0.0.1:49698
2019-01-31 03:17:49 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:49 Received a POST request for / from 127.0.0.1:49700
2019-01-31 03:17:49 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:49 Received a POST request for / from 127.0.0.1:49702
2019-01-31 03:17:49 ThreadRPCServer method=getrawtransaction
2019-01-31 03:17:49 Received a POST request for / from 127.0.0.1:49704
2019-01-31 03:17:49 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:49 Received a POST request for / from 127.0.0.1:49706
2019-01-31 03:17:49 ThreadRPCServer method=getblock
2019-01-31 03:17:49 Received a POST request for / from 127.0.0.1:49708
2019-01-31 03:17:49 ThreadRPCServer method=getblockheader
2019-01-31 03:17:49 Received a POST request for / from 127.0.0.1:49710
2019-01-31 03:17:49 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:49 Received a POST request for / from 127.0.0.1:49712
2019-01-31 03:17:49 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:49 connection to 46.219.111.171:8333 timeout
2019-01-31 03:17:50 trying connection [2406:e006:29:cb01:960c:6dff:fe80:61b]:8333 lastseen=374.4hrs
2019-01-31 03:17:50 connect() to [2406:e006:29:cb01:960c:6dff:fe80:61b]:8333 failed: Network is unreachable (101)
2019-01-31 03:17:50 trying connection 93.75.18.151:8333 lastseen=9.1hrs
2019-01-31 03:17:50 Added connection peer=7
2019-01-31 03:17:50 sending version (102 bytes) peer=7
2019-01-31 03:17:50 send version message: version 70015, blocks=560846, us=[::]:0, peer=7
2019-01-31 03:17:51 received: version (104 bytes) peer=7
2019-01-31 03:17:51 sending verack (0 bytes) peer=7
2019-01-31 03:17:51 ProcessMessages: advertising address 13.92.254.226:8335
2019-01-31 03:17:51 sending getaddr (0 bytes) peer=7
2019-01-31 03:17:51 receive version message: /Satoshi:0.17.0.1/: version 70015, blocks=560846, us=13.92.254.226:41950, peer=7
2019-01-31 03:17:51 added time data, samples 8, offset +2 (+0 minutes)
2019-01-31 03:17:51 received: verack (0 bytes) peer=7
2019-01-31 03:17:51 New outbound peer connected: version: 70015, blocks=560846, peer=7
2019-01-31 03:17:51 sending sendheaders (0 bytes) peer=7
2019-01-31 03:17:51 sending sendcmpct (9 bytes) peer=7
2019-01-31 03:17:51 sending sendcmpct (9 bytes) peer=7
2019-01-31 03:17:51 sending ping (8 bytes) peer=7
2019-01-31 03:17:51 AdvertiseLocal: advertising address 13.92.254.226:8335
2019-01-31 03:17:51 sending addr (31 bytes) peer=7
2019-01-31 03:17:51 initial getheaders (560845) to peer=7 (startheight:560846)
2019-01-31 03:17:51 sending getheaders (1029 bytes) peer=7
2019-01-31 03:17:51 received: sendheaders (0 bytes) peer=7
2019-01-31 03:17:51 received: sendcmpct (9 bytes) peer=7
2019-01-31 03:17:51 received: sendcmpct (9 bytes) peer=7
2019-01-31 03:17:51 received: ping (8 bytes) peer=7
2019-01-31 03:17:51 sending pong (8 bytes) peer=7
2019-01-31 03:17:51 received: addr (31 bytes) peer=7
2019-01-31 03:17:51 received: getheaders (1029 bytes) peer=7
2019-01-31 03:17:51 getheaders 560846 to end from peer=7
2019-01-31 03:17:51 sending headers (82 bytes) peer=7
2019-01-31 03:17:51 received: feefilter (8 bytes) peer=7
2019-01-31 03:17:51 received: feefilter of 0.00001000 BTC/kB from peer=7
2019-01-31 03:17:51 received: pong (8 bytes) peer=7
2019-01-31 03:17:51 received: headers (82 bytes) peer=7
2019-01-31 03:17:51 trying connection 49.64.33.243:8333 lastseen=4080.2hrs
2019-01-31 03:17:53 tor: Error connecting to Tor control socket
2019-01-31 03:17:53 tor: Not connected to Tor control port 127.0.0.1:9051, trying to reconnect
2019-01-31 03:17:54 Received a POST request for / from 127.0.0.1:49732
2019-01-31 03:17:54 ThreadRPCServer method=getblockchaininfo
2019-01-31 03:17:54 Received a POST request for / from 127.0.0.1:49734
2019-01-31 03:17:54 ThreadRPCServer method=getblockhash
2019-01-31 03:17:54 Received a POST request for / from 127.0.0.1:49736
2019-01-31 03:17:54 ThreadRPCServer method=getblockhash
2019-01-31 03:17:54 Received a POST request for / from 127.0.0.1:49738
2019-01-31 03:17:54 ThreadRPCServer method=getblock
2019-01-31 03:17:54 Received a POST request for / from 127.0.0.1:49740
2019-01-31 03:17:54 ThreadRPCServer method=getblockheader
2019-01-31 03:17:54 Received a POST request for / from 127.0.0.1:49742
2019-01-31 03:17:54 ThreadRPCServer method=getblockhash
2019-01-31 03:17:54 Received a POST request for / from 127.0.0.1:49744
2019-01-31 03:17:54 ThreadRPCServer method=getblock
2019-01-31 03:17:54 Received a POST request for / from 127.0.0.1:49746
2019-01-31 03:17:54 ThreadRPCServer method=getblockheader
2019-01-31 03:17:55 sending addr (31 bytes) peer=3
2019-01-31 03:17:56 connection to 49.64.33.243:8333 timeout
2019-01-31 03:17:56 sending addr (31 bytes) peer=2
2019-01-31 03:17:56 trying connection [2001:999:0:73fb:1044:9f:8e65:3]:8333 lastseen=483.9hrs
2019-01-31 03:17:56 connect() to [2001:999:0:73fb:1044:9f:8e65:3]:8333 failed: Network is unreachable (101)
2019-01-31 03:17:57 trying connection 121.44.112.79:8333 lastseen=519.2hrs
2019-01-31 03:17:58 Received a POST request for / from 127.0.0.1:49766
2019-01-31 03:17:58 ThreadRPCServer method=getblockhash
2019-01-31 03:17:58 Received a POST request for / from 127.0.0.1:49768
2019-01-31 03:17:58 ThreadRPCServer method=getblockhash
2019-01-31 03:17:58 Received a POST request for / from 127.0.0.1:49770
2019-01-31 03:17:58 ThreadRPCServer method=getblockhash
2019-01-31 03:17:58 Received a POST request for / from 127.0.0.1:49772
2019-01-31 03:17:58 ThreadRPCServer method=getblock
2019-01-31 03:17:58 Received a POST request for / from 127.0.0.1:49774
2019-01-31 03:17:58 ThreadRPCServer method=getblock
2019-01-31 03:17:58 Received a POST request for / from 127.0.0.1:49776
2019-01-31 03:17:58 ThreadRPCServer method=getblock
2019-01-31 03:17:58 Received a POST request for / from 127.0.0.1:49778
2019-01-31 03:17:58 ThreadRPCServer method=gettxout
2019-01-31 03:17:58 Received a POST request for / from 127.0.0.1:49780
2019-01-31 03:17:58 ThreadRPCServer method=gettxout
2019-01-31 03:17:59 Received a POST request for / from 127.0.0.1:49782
2019-01-31 03:17:59 ThreadRPCServer method=gettxout
2019-01-31 03:17:59 Received a POST request for / from 127.0.0.1:49790
2019-01-31 03:17:59 ThreadRPCServer method=getblockhash
2019-01-31 03:17:59 Received a POST request for / from 127.0.0.1:49792
2019-01-31 03:17:59 ThreadRPCServer method=getblock
2019-01-31 03:17:59 Received a POST request for / from 127.0.0.1:49794
2019-01-31 03:17:59 ThreadRPCServer method=gettxout
2019-01-31 03:17:59 Received a POST request for / from 127.0.0.1:49796
2019-01-31 03:17:59 ThreadRPCServer method=getblockhash
2019-01-31 03:17:59 Received a POST request for / from 127.0.0.1:49798
2019-01-31 03:17:59 ThreadRPCServer method=getblock
2019-01-31 03:17:59 Received a POST request for / from 127.0.0.1:49800
2019-01-31 03:17:59 ThreadRPCServer method=gettxout
2019-01-31 03:17:59 Received a POST request for / from 127.0.0.1:49802
2019-01-31 03:17:59 ThreadRPCServer method=getblockhash
2019-01-31 03:17:59 Received a POST request for / from 127.0.0.1:49804
2019-01-31 03:17:59 ThreadRPCServer method=getblock
2019-01-31 03:17:59 Received a POST request for / from 127.0.0.1:49806
2019-01-31 03:17:59 ThreadRPCServer method=gettxout
2019-01-31 03:18:00 Received a POST request for / from 127.0.0.1:49808
2019-01-31 03:18:00 ThreadRPCServer method=getblockhash
2019-01-31 03:18:00 Received a POST request for / from 127.0.0.1:49810
2019-01-31 03:18:00 ThreadRPCServer method=getblock
2019-01-31 03:18:00 Received a POST request for / from 127.0.0.1:49812
2019-01-31 03:18:00 ThreadRPCServer method=gettxout
2019-01-31 03:18:00 Received a POST request for / from 127.0.0.1:49814
2019-01-31 03:18:00 ThreadRPCServer method=getblockhash
2019-01-31 03:18:00 Received a POST request for / from 127.0.0.1:49816
2019-01-31 03:18:00 ThreadRPCServer method=getblock
2019-01-31 03:18:00 Received a POST request for / from 127.0.0.1:49818
2019-01-31 03:18:00 ThreadRPCServer method=gettxout
2019-01-31 03:18:00 Received a POST request for / from 127.0.0.1:49820
2019-01-31 03:18:00 ThreadRPCServer method=getblockhash
2019-01-31 03:18:00 Received a POST request for / from 127.0.0.1:49822
2019-01-31 03:18:00 ThreadRPCServer method=getblock
2019-01-31 03:18:00 Received a POST request for / from 127.0.0.1:49824
2019-01-31 03:18:00 ThreadRPCServer method=gettxout
2019-01-31 03:18:01 Received a POST request for / from 127.0.0.1:49826
2019-01-31 03:18:01 ThreadRPCServer method=getblockhash
2019-01-31 03:18:01 Received a POST request for / from 127.0.0.1:49828
2019-01-31 03:18:01 ThreadRPCServer method=getblock
2019-01-31 03:18:01 Received a POST request for / from 127.0.0.1:49830
2019-01-31 03:18:01 ThreadRPCServer method=gettxout
2019-01-31 03:18:01 Received a POST request for / from 127.0.0.1:49832
2019-01-31 03:18:01 ThreadRPCServer method=getblockhash
2019-01-31 03:18:01 Received a POST request for / from 127.0.0.1:49834
2019-01-31 03:18:01 ThreadRPCServer method=getblock
2019-01-31 03:18:01 Received a POST request for / from 127.0.0.1:49836
2019-01-31 03:18:01 ThreadRPCServer method=gettxout
2019-01-31 03:18:01 Received a POST request for / from 127.0.0.1:49838
2019-01-31 03:18:01 ThreadRPCServer method=getblockhash
2019-01-31 03:18:01 Received a POST request for / from 127.0.0.1:49840
2019-01-31 03:18:01 ThreadRPCServer method=getblock
2019-01-31 03:18:01 Received a POST request for / from 127.0.0.1:49842
2019-01-31 03:18:01 ThreadRPCServer method=gettxout
2019-01-31 03:18:02 Received a POST request for / from 127.0.0.1:49844
2019-01-31 03:18:02 ThreadRPCServer method=getblockhash
2019-01-31 03:18:02 Received a POST request for / from 127.0.0.1:49846
2019-01-31 03:18:02 ThreadRPCServer method=getblock
2019-01-31 03:18:02 Received a POST request for / from 127.0.0.1:49854
2019-01-31 03:18:02 ThreadRPCServer method=gettxout
2019-01-31 03:18:02 Received a POST request for / from 127.0.0.1:49856
2019-01-31 03:18:02 ThreadRPCServer method=getblockhash
2019-01-31 03:18:02 Received a POST request for / from 127.0.0.1:49858
2019-01-31 03:18:02 ThreadRPCServer method=getblock
2019-01-31 03:18:02 connection to 121.44.112.79:8333 timeout
2019-01-31 03:18:02 Received a POST request for / from 127.0.0.1:49860
2019-01-31 03:18:02 ThreadRPCServer method=gettxout
2019-01-31 03:18:02 Received a POST request for / from 127.0.0.1:49862
2019-01-31 03:18:02 ThreadRPCServer method=getblockhash
2019-01-31 03:18:02 Received a POST request for / from 127.0.0.1:49864
2019-01-31 03:18:02 ThreadRPCServer method=getblock
2019-01-31 03:18:02 Received a POST request for / from 127.0.0.1:49866
2019-01-31 03:18:02 ThreadRPCServer method=gettxout
2019-01-31 03:18:02 trying connection 151.80.21.57:8333 lastseen=1869.3hrs
2019-01-31 03:18:02 connect() to 151.80.21.57:8333 failed after select(): Connection refused (111)
2019-01-31 03:18:02 Received a POST request for / from 127.0.0.1:49870
2019-01-31 03:18:02 ThreadRPCServer method=getblockhash
2019-01-31 03:18:02 Received a POST request for / from 127.0.0.1:49872
2019-01-31 03:18:02 ThreadRPCServer method=getblock
2019-01-31 03:18:03 Received a POST request for / from 127.0.0.1:49874
2019-01-31 03:18:03 ThreadRPCServer method=gettxout
2019-01-31 03:18:03 Received a POST request for / from 127.0.0.1:49876
2019-01-31 03:18:03 ThreadRPCServer method=getblockhash
2019-01-31 03:18:03 Received a POST request for / from 127.0.0.1:49878
2019-01-31 03:18:03 ThreadRPCServer method=getblock
2019-01-31 03:18:03 trying connection 122.191.248.87:8333 lastseen=529.8hrs
2019-01-31 03:18:03 Received a POST request for / from 127.0.0.1:49882
2019-01-31 03:18:03 ThreadRPCServer method=gettxout
2019-01-31 03:18:03 Received a POST request for / from 127.0.0.1:49884
2019-01-31 03:18:03 ThreadRPCServer method=getblockhash
2019-01-31 03:18:03 Received a POST request for / from 127.0.0.1:49886
2019-01-31 03:18:03 ThreadRPCServer method=getblock
2019-01-31 03:18:03 Received a POST request for / from 127.0.0.1:49888
2019-01-31 03:18:03 ThreadRPCServer method=gettxout
2019-01-31 03:18:04 Received a POST request for / from 127.0.0.1:49890
2019-01-31 03:18:04 ThreadRPCServer method=getblockhash
2019-01-31 03:18:04 Received a POST request for / from 127.0.0.1:49892
2019-01-31 03:18:04 ThreadRPCServer method=getblock

See also the LND startup:

2019-01-31 03:17:45.977 [INF] UTXN: (Re)-sweeping 5 heights below height=560846
2019-01-31 03:17:45.977 [INF] UTXN: Attempting to graduate height=527663: num_kids=1, num_babies=0
2019-01-31 03:17:45.977 [INF] UTXN: Sweeping 1 CSV-delayed outputs with sweep tx for height 527663
2019-01-31 03:17:45.977 [INF] SWPR: Sweep request received: out_point=5e2d590fcc48098ff6fe0dee6d6a2f624190fc80f0fd7964396c4e08c2526bf1:0, witness_type=CommitmentTimeLock, time_lock=144, size=0.00000733 BTC
2019-01-31 03:17:45.977 [INF] NTFN: New spend subscription: spend_id=1, outpoint=5e2d590fcc48098ff6fe0dee6d6a2f624190fc80f0fd7964396c4e08c2526bf1:0, height_hint=527519
2019-01-31 03:17:45.978 [INF] UTXN: Attempting to graduate height=542671: num_kids=1, num_babies=0
2019-01-31 03:17:45.978 [INF] UTXN: Sweeping 1 CSV-delayed outputs with sweep tx for height 542671
2019-01-31 03:17:45.978 [INF] SWPR: Sweep request received: out_point=bcec52500748200ed0848ddfad1e9ed30f7ae1c552c528bbd9da69d52a291f59:0, witness_type=CommitmentTimeLock, time_lock=144, size=0.00000602 BTC
2019-01-31 03:17:46.100 [INF] SWPR: Sweep candidates at height=560846, yield 0 distinct txns
2019-01-31 03:17:46.100 [INF] NTFN: New spend subscription: spend_id=2, outpoint=bcec52500748200ed0848ddfad1e9ed30f7ae1c552c528bbd9da69d52a291f59:0, height_hint=542527
2019-01-31 03:17:46.100 [INF] UTXN: Attempting to graduate height=560194: num_kids=1, num_babies=0
2019-01-31 03:17:46.100 [INF] UTXN: Sweeping 1 CSV-delayed outputs with sweep tx for height 560194
2019-01-31 03:17:46.100 [INF] SWPR: Sweep request received: out_point=57addab6ccb2a6a1390367e02a1219f1a372e57295971193685459f4931af919:0, witness_type=CommitmentTimeLock, time_lock=144, size=0.00000573 BTC
2019-01-31 03:17:46.254 [INF] SWPR: Sweep candidates at height=560846, yield 0 distinct txns
2019-01-31 03:17:46.254 [INF] NTFN: New spend subscription: spend_id=3, outpoint=57addab6ccb2a6a1390367e02a1219f1a372e57295971193685459f4931af919:0, height_hint=560050
2019-01-31 03:17:46.255 [INF] UTXN: Attempting to graduate height=560282: num_kids=1, num_babies=0
2019-01-31 03:17:46.255 [INF] UTXN: Sweeping 1 CSV-delayed outputs with sweep tx for height 560282
2019-01-31 03:17:46.255 [INF] SWPR: Sweep request received: out_point=15ea01435c9d6fc9433d581254c507e74a89a7b6c9572f048011996a94724517:0, witness_type=CommitmentTimeLock, time_lock=144, size=0.00000579 BTC
2019-01-31 03:17:46.497 [INF] SWPR: Sweep candidates at height=560846, yield 0 distinct txns
2019-01-31 03:17:46.497 [INF] NTFN: New spend subscription: spend_id=4, outpoint=15ea01435c9d6fc9433d581254c507e74a89a7b6c9572f048011996a94724517:0, height_hint=560138
2019-01-31 03:17:46.498 [INF] UTXN: Attempting to graduate height=560735: num_kids=1, num_babies=0
2019-01-31 03:17:46.498 [INF] UTXN: Sweeping 1 CSV-delayed outputs with sweep tx for height 560735
2019-01-31 03:17:46.498 [INF] SWPR: Sweep request received: out_point=e05b05e86a6d192645fa01365ef503b360d807d78575f0391e0d4aae326ea9af:1, witness_type=CommitmentTimeLock, time_lock=600, size=0.02586729 BTC
2019-01-31 03:17:46.613 [INF] SWPR: Sweep candidates at height=560846, yield 0 distinct txns
2019-01-31 03:17:46.613 [INF] UTXN: UTXO Nursery is now fully synced
2019-01-31 03:17:46.613 [INF] NTFN: New spend subscription: spend_id=5, outpoint=e05b05e86a6d192645fa01365ef503b360d807d78575f0391e0d4aae326ea9af:1, height_hint=560135
2019-01-31 03:17:46.613 [INF] NTFN: New block epoch subscription
2019-01-31 03:17:46.767 [INF] SWPR: Candidate sweep set of size=1, has yield=0.02585429 BTC
2019-01-31 03:17:46.767 [INF] SWPR: Sweep candidates at height=560846, yield 1 distinct txns
2019-01-31 03:17:46.795 [INF] CNCT: Creating ChannelArbitrators for 17 closing channels
2019-01-31 03:17:46.795 [INF] NTFN: New block epoch subscription
2019-01-31 03:17:46.795 [INF] NTFN: New block epoch subscription
2019-01-31 03:17:46.795 [INF] NTFN: New block epoch subscription
2019-01-31 03:17:46.795 [INF] NTFN: New block epoch subscription
2019-01-31 03:17:46.795 [INF] NTFN: New block epoch subscription
2019-01-31 03:17:46.796 [INF] NTFN: New block epoch subscription
2019-01-31 03:17:46.796 [INF] NTFN: New block epoch subscription
2019-01-31 03:17:46.796 [INF] NTFN: New block epoch subscription
2019-01-31 03:17:46.796 [INF] NTFN: New block epoch subscription
2019-01-31 03:17:46.796 [INF] NTFN: New block epoch subscription
2019-01-31 03:17:46.796 [INF] NTFN: New block epoch subscription
2019-01-31 03:17:46.796 [INF] NTFN: New block epoch subscription
2019-01-31 03:17:46.796 [INF] NTFN: New block epoch subscription
2019-01-31 03:17:46.796 [INF] NTFN: New block epoch subscription
2019-01-31 03:17:46.796 [INF] NTFN: New block epoch subscription
2019-01-31 03:17:46.796 [INF] NTFN: New block epoch subscription
2019-01-31 03:17:46.797 [INF] NTFN: New block epoch subscription
2019-01-31 03:17:46.797 [INF] CNCT: ChannelArbitrator(5dfc4e79307094c0ce821d2c67bc89f0bb9e12d47546fa69218196bc6beb3f21:1): starting state=StateWaitingFullResolution
2019-01-31 03:17:46.810 [INF] CNCT: ChannelArbitrator(5dfc4e79307094c0ce821d2c67bc89f0bb9e12d47546fa69218196bc6beb3f21:1): still awaiting contract resolution
2019-01-31 03:17:46.811 [INF] CNCT: ChannelArbitrator(5dfc4e79307094c0ce821d2c67bc89f0bb9e12d47546fa69218196bc6beb3f21:1): relaunching 1 contract resolvers
2019-01-31 03:17:46.811 [INF] CNCT: ChannelArbitrator(8c6cc58b545ce59bfd24f91fdf683093851cad6dcb7fc1012176ef159158e839:1): starting state=StateContractClosed
2019-01-31 03:17:46.811 [INF] NTFN: New confirmation subscription: txid=15ea01435c9d6fc9433d581254c507e74a89a7b6c9572f048011996a94724517, num_confs=1
2019-01-31 03:17:46.812 [ERR] CNCT: unable to fetch contract resolutions: no contract resolutions exist
2019-01-31 03:17:46.812 [ERR] CNCT: ChannelArbitrator(8c6cc58b545ce59bfd24f91fdf683093851cad6dcb7fc1012176ef159158e839:1): unable to advance state: no contract resolutions exist
2019-01-31 03:17:46.812 [WRN] CNCT: ChannelArbitrator(8c6cc58b545ce59bfd24f91fdf683093851cad6dcb7fc1012176ef159158e839:1): detected closedchannel with no contract resolutions written.
2019-01-31 03:17:46.813 [INF] CNCT: ChannelArbitrator(4a1d62d72c8848c58fb90f5235670436489b21aa22774789288f79e6a2b1c3aa:1): starting state=StateWaitingFullResolution
2019-01-31 03:17:46.815 [INF] CNCT: ChannelArbitrator(4a1d62d72c8848c58fb90f5235670436489b21aa22774789288f79e6a2b1c3aa:1): still awaiting contract resolution
2019-01-31 03:17:46.815 [INF] CNCT: ChannelArbitrator(4a1d62d72c8848c58fb90f5235670436489b21aa22774789288f79e6a2b1c3aa:1): relaunching 1 contract resolvers
2019-01-31 03:17:46.816 [INF] CNCT: ChannelArbitrator(54259ec27ef84973bb905611e5aa2b84f4a6ae40876c605cabfbb3545d4f33c1:0): starting state=StateContractClosed
2019-01-31 03:17:46.816 [INF] NTFN: New confirmation subscription: txid=7a03fe4870bfb51dfec7a9ff311294d0d233c32feb9e6917ca559f503b2666bc, num_confs=1
2019-01-31 03:17:46.952 [ERR] CNCT: unable to fetch contract resolutions: no contract resolutions exist
2019-01-31 03:17:46.952 [ERR] CNCT: ChannelArbitrator(54259ec27ef84973bb905611e5aa2b84f4a6ae40876c605cabfbb3545d4f33c1:0): unable to advance state: no contract resolutions exist
2019-01-31 03:17:46.952 [WRN] CNCT: ChannelArbitrator(54259ec27ef84973bb905611e5aa2b84f4a6ae40876c605cabfbb3545d4f33c1:0): detected closedchannel with no contract resolutions written.
2019-01-31 03:17:46.952 [INF] CNCT: ChannelArbitrator(39389828ccded50ad1d380ee0fc59c9f9fa7224f4fe6bfe2c58c6772592b34c8:1): starting state=StateWaitingFullResolution
2019-01-31 03:17:46.954 [INF] CNCT: ChannelArbitrator(39389828ccded50ad1d380ee0fc59c9f9fa7224f4fe6bfe2c58c6772592b34c8:1): still awaiting contract resolution
2019-01-31 03:17:46.954 [INF] CNCT: ChannelArbitrator(39389828ccded50ad1d380ee0fc59c9f9fa7224f4fe6bfe2c58c6772592b34c8:1): relaunching 1 contract resolvers
2019-01-31 03:17:46.955 [INF] CNCT: ChannelArbitrator(2a4683fed472f26b08e2567b46e99ab3e606ae2a1887e83cbaff82a7dc6af00c:0): starting state=StateWaitingFullResolution
2019-01-31 03:17:46.955 [INF] NTFN: New confirmation subscription: txid=3b4d9999553ac56561fb49a38d8adf327cf0051f210150edde7e0f36111a1ae4, num_confs=1
2019-01-31 03:17:47.052 [INF] NTFN: Dispatching 1 confirmation notification for txid=15ea01435c9d6fc9433d581254c507e74a89a7b6c9572f048011996a94724517
2019-01-31 03:17:47.052 [INF] NTFN: New spend subscription: spend_id=6, outpoint=15ea01435c9d6fc9433d581254c507e74a89a7b6c9572f048011996a94724517:0, height_hint=560138
2019-01-31 03:17:47.052 [INF] CNCT: *contractcourt.commitSweepResolver(5dfc4e79307094c0ce821d2c67bc89f0bb9e12d47546fa69218196bc6beb3f21:1): waiting for commit output to be swept
2019-01-31 03:17:47.061 [INF] CNCT: ChannelArbitrator(2a4683fed472f26b08e2567b46e99ab3e606ae2a1887e83cbaff82a7dc6af00c:0): still awaiting contract resolution
2019-01-31 03:17:47.064 [INF] CNCT: ChannelArbitrator(2a4683fed472f26b08e2567b46e99ab3e606ae2a1887e83cbaff82a7dc6af00c:0): relaunching 1 contract resolvers
2019-01-31 03:17:47.065 [INF] CNCT: ChannelArbitrator(883f4b2cc4629d495bff2accca14d389b6e76e5174cb7ffe6fc3fd3f3ff4f111:0): starting state=StateWaitingFullResolution
2019-01-31 03:17:47.065 [INF] CNCT: *contractcourt.htlcSuccessResolver(55932bb2f35fd5457cb1fa7c51d8f89ac8aa2163420b54e7f0509bdf1806f96e): crafting sweep tx for incoming+remote htlc confirmed
2019-01-31 03:17:47.111 [INF] CNCT: ChannelArbitrator(883f4b2cc4629d495bff2accca14d389b6e76e5174cb7ffe6fc3fd3f3ff4f111:0): still awaiting contract resolution
2019-01-31 03:17:47.178 [INF] CNCT: ChannelArbitrator(883f4b2cc4629d495bff2accca14d389b6e76e5174cb7ffe6fc3fd3f3ff4f111:0): relaunching 1 contract resolvers
2019-01-31 03:17:47.178 [INF] CNCT: ChannelArbitrator(e612b571044b5386d1c15babd701823ea164ab045a8a189552ea6739540c8d1b:1): starting state=StateWaitingFullResolution
2019-01-31 03:17:47.178 [INF] NTFN: New confirmation subscription: txid=5e2d590fcc48098ff6fe0dee6d6a2f624190fc80f0fd7964396c4e08c2526bf1, num_confs=1
2019-01-31 03:17:47.186 [INF] NTFN: Dispatching 1 confirmation notification for txid=7a03fe4870bfb51dfec7a9ff311294d0d233c32feb9e6917ca559f503b2666bc
2019-01-31 03:17:47.217 [INF] CNCT: ChannelArbitrator(e612b571044b5386d1c15babd701823ea164ab045a8a189552ea6739540c8d1b:1): still awaiting contract resolution
2019-01-31 03:17:47.217 [INF] CNCT: ChannelArbitrator(e612b571044b5386d1c15babd701823ea164ab045a8a189552ea6739540c8d1b:1): relaunching 1 contract resolvers
2019-01-31 03:17:47.219 [INF] NTFN: New confirmation subscription: txid=e05b05e86a6d192645fa01365ef503b360d807d78575f0391e0d4aae326ea9af, num_confs=1
2019-01-31 03:17:47.234 [INF] CNCT: ChannelArbitrator(f5c6598c5ad95bdd7335eeb2ec8f8cda4829d7bdb974447216edfc8f3c3df9ee:1): starting state=StateWaitingFullResolution
2019-01-31 03:17:47.235 [INF] CNCT: ChannelArbitrator(f5c6598c5ad95bdd7335eeb2ec8f8cda4829d7bdb974447216edfc8f3c3df9ee:1): still awaiting contract resolution
2019-01-31 03:17:47.235 [INF] CNCT: ChannelArbitrator(f5c6598c5ad95bdd7335eeb2ec8f8cda4829d7bdb974447216edfc8f3c3df9ee:1): relaunching 1 contract resolvers
2019-01-31 03:17:47.236 [INF] NTFN: New confirmation subscription: txid=e0eb8dbca98a908d73f8f269bf53c0b67cb0eb09f76110de44f6b349352a1238, num_confs=1
2019-01-31 03:17:47.294 [INF] SWPR: Creating sweep transaction for 1 inputs (0 CSV, 0 CLTV) using 2676 sat/kw
2019-01-31 03:17:47.294 [INF] CNCT: ChannelArbitrator(c51bab31943e3341429d89dd5f64b0b7ca66ab6326b9cde22737c52b56f9a6f5:1): starting state=StateContractClosed
2019-01-31 03:17:47.295 [INF] CNCT: *contractcourt.htlcSuccessResolver(55932bb2f35fd5457cb1fa7c51d8f89ac8aa2163420b54e7f0509bdf1806f96e): crafted sweep tx=(*wire.MsgTx)(0xc00007b780)({
 Version: (int32) 2,
 TxIn: ([]*wire.TxIn) (len=1 cap=15) {
  (*wire.TxIn)(0xc0002f7800)({
   PreviousOutPoint: (wire.OutPoint) e730488549fc7990f0e7ab72a7d8f2daefb6b89a97c5f77d673d1c1fbd5b3525:4,
   SignatureScript: ([]uint8) <nil>,
   Witness: (wire.TxWitness) (len=3 cap=3) {
    ([]uint8) (len=72 cap=144) {
     00000000  30 45 02 21 00 f2 f4 90  1a 2e 34 32 ba 99 43 e6  |0E.!......42..C.|
     00000010  d5 d4 c0 11 fe 73 90 0e  1b 3d eb 77 10 d5 f7 9c  |.....s...=.w....|
     00000020  60 c9 96 cf 96 02 20 0f  93 f2 0d 23 6a 2a 29 02  |`..... ....#j*).|
     00000030  3f b3 e3 be 06 ed 25 4c  d3 77 c0 7f 52 7d 6f f2  |?.....%L.w..R}o.|
     00000040  2d ae ac 35 16 c1 c3 01                           |-..5....|
    },
    ([]uint8) (len=32 cap=32) {
     00000000  a2 9c 20 88 66 55 1e d2  62 d9 6b 6a 0c 66 48 b9  |.. .fU..b.kj.fH.|
     00000010  41 cd ca 39 a3 21 f2 ac  42 60 89 ae e0 95 03 c3  |A..9.!..B`......|
    },
    ([]uint8) (len=133 cap=133) {
     00000000  76 a9 14 57 2a 91 d9 50  3e 3e f0 11 a4 e5 ec 94  |v..W*..P>>......|
     00000010  9f 57 35 d2 ac db e1 87  63 ac 67 21 03 19 a9 c4  |.W5.....c.g!....|
     00000020  7e 18 64 79 be c4 03 27  ef cd fc 63 91 ce f3 e2  |~.dy...'...c....|
     00000030  05 0e 26 7f 45 29 00 d5  63 83 aa b4 a6 7c 82 01  |..&.E)..c....|..|
     00000040  20 87 64 75 52 7c 21 03  5c 47 50 35 11 d1 17 30  | .duR|!.\GP5...0|
     00000050  a6 14 c3 7b 4c 46 2b a4  b3 03 3c 67 cd f9 09 4a  |...{LF+...<g...J|
     00000060  6e 0c 60 32 aa a9 ab f8  52 ae 67 a9 14 54 09 d5  |n.`2....R.g..T..|
     00000070  9c 8a c1 bf 9b be 05 04  73 a9 1d 6c f3 8e a3 4c  |........s..l...L|
     00000080  c8 88 ac 68 68                                    |...hh|
    }
   },
   Sequence: (uint32) 0
  })
 },
 TxOut: ([]*wire.TxOut) (len=1 cap=15) {
  (*wire.TxOut)(0xc0029f9080)({
   Value: (int64) 340070,
   PkScript: ([]uint8) (len=22 cap=500) {
    00000000  00 14 ea da bb ed 56 88  38 68 83 23 be 43 ab 7e  |......V.8h.#.C.~|
    00000010  de f8 fb c0 9d 9c                                 |......|
   }
  })
 },
 LockTime: (uint32) 0
})

2019-01-31 03:17:47.299 [INF] NTFN: Dispatching confirmed spend notification for outpoint=e05b05e86a6d192645fa01365ef503b360d807d78575f0391e0d4aae326ea9af:1 at height=560846
2019-01-31 03:17:47.299 [INF] NTFN: Canceling spend notification: spend_id=5, outpoint=e05b05e86a6d192645fa01365ef503b360d807d78575f0391e0d4aae326ea9af:1
2019-01-31 03:17:47.299 [INF] NTFN: New spend subscription: spend_id=7, outpoint=7a03fe4870bfb51dfec7a9ff311294d0d233c32feb9e6917ca559f503b2666bc:1, height_hint=560200
2019-01-31 03:17:47.299 [INF] UTXN: Height bucket 560735 pruned
2019-01-31 03:17:47.299 [ERR] CNCT: unable to fetch contract resolutions: no contract resolutions exist
2019-01-31 03:17:47.299 [ERR] CNCT: ChannelArbitrator(c51bab31943e3341429d89dd5f64b0b7ca66ab6326b9cde22737c52b56f9a6f5:1): unable to advance state: no contract resolutions exist
2019-01-31 03:17:47.299 [WRN] CNCT: ChannelArbitrator(c51bab31943e3341429d89dd5f64b0b7ca66ab6326b9cde22737c52b56f9a6f5:1): detected closedchannel with no contract resolutions written.
2019-01-31 03:17:47.300 [INF] CNCT: ChannelArbitrator(9cebba83a510e9b2d52bbaeb9986b9e57ba86ff7adec1310c6afda253334a408:0): starting state=StateWaitingFullResolution
2019-01-31 03:17:47.386 [INF] UTXN: Graduated kindergarten output from height=560735
2019-01-31 03:17:47.465 [INF] CNCT: ChannelArbitrator(9cebba83a510e9b2d52bbaeb9986b9e57ba86ff7adec1310c6afda253334a408:0): still awaiting contract resolution
2019-01-31 03:17:47.488 [INF] NTFN: Dispatching 1 confirmation notification for txid=3b4d9999553ac56561fb49a38d8adf327cf0051f210150edde7e0f36111a1ae4
2019-01-31 03:17:47.490 [INF] CNCT: ChannelArbitrator(9cebba83a510e9b2d52bbaeb9986b9e57ba86ff7adec1310c6afda253334a408:0): relaunching 1 contract resolvers
2019-01-31 03:17:47.501 [INF] LNWL: Inserting unconfirmed transaction afe236d78af823288e79484d9bcf5368e97064e237eed6308f97edf903e5c117
2019-01-31 03:17:47.534 [INF] NTFN: New spend subscription: spend_id=8, outpoint=3b4d9999553ac56561fb49a38d8adf327cf0051f210150edde7e0f36111a1ae4:0, height_hint=560200
2019-01-31 03:17:47.534 [INF] NTFN: New confirmation subscription: txid=bcec52500748200ed0848ddfad1e9ed30f7ae1c552c528bbd9da69d52a291f59, num_confs=1
2019-01-31 03:17:47.534 [INF] CNCT: ChannelArbitrator(2dcfbe36edb2c40d221356868ff415b3179deb3d39561a307a93f3307e83bebf:0): starting state=StateContractClosed
2019-01-31 03:17:47.639 [INF] UTXN: Removed channel e612b571044b5386d1c15babd701823ea164ab045a8a189552ea6739540c8d1b:1 from nursery store
2019-01-31 03:17:47.640 [ERR] CNCT: unable to fetch contract resolutions: no contract resolutions exist
2019-01-31 03:17:47.640 [ERR] CNCT: ChannelArbitrator(2dcfbe36edb2c40d221356868ff415b3179deb3d39561a307a93f3307e83bebf:0): unable to advance state: no contract resolutions exist
2019-01-31 03:17:47.640 [WRN] CNCT: ChannelArbitrator(2dcfbe36edb2c40d221356868ff415b3179deb3d39561a307a93f3307e83bebf:0): detected closedchannel with no contract resolutions written.
2019-01-31 03:17:47.640 [INF] CNCT: ChannelArbitrator(f567819c8f9526d62ce2d14eea91a707fe713a4e18ae0ad89a0dd303aea9b836:0): starting state=StateContractClosed
2019-01-31 03:17:47.740 [INF] CNCT: *contractcourt.commitSweepResolver(4a1d62d72c8848c58fb90f5235670436489b21aa22774789288f79e6a2b1c3aa:1): waiting for commit output to be swept
2019-01-31 03:17:47.837 [INF] NTFN: Dispatching 1 confirmation notification for txid=5e2d590fcc48098ff6fe0dee6d6a2f624190fc80f0fd7964396c4e08c2526bf1
2019-01-31 03:17:47.954 [INF] CNCT: *contractcourt.commitSweepResolver(39389828ccded50ad1d380ee0fc59c9f9fa7224f4fe6bfe2c58c6772592b34c8:1): waiting for commit output to be swept
2019-01-31 03:17:47.954 [INF] NTFN: New spend subscription: spend_id=9, outpoint=5e2d590fcc48098ff6fe0dee6d6a2f624190fc80f0fd7964396c4e08c2526bf1:0, height_hint=527519
2019-01-31 03:17:47.955 [INF] CNCT: *contractcourt.commitSweepResolver(883f4b2cc4629d495bff2accca14d389b6e76e5174cb7ffe6fc3fd3f3ff4f111:0): waiting for commit output to be swept
2019-01-31 03:17:48.222 [INF] NTFN: Dispatching 1 confirmation notification for txid=e05b05e86a6d192645fa01365ef503b360d807d78575f0391e0d4aae326ea9af
2019-01-31 03:17:48.222 [INF] NTFN: New spend subscription: spend_id=10, outpoint=e05b05e86a6d192645fa01365ef503b360d807d78575f0391e0d4aae326ea9af:1, height_hint=560135
2019-01-31 03:17:48.222 [INF] NTFN: Dispatching confirmed spend notification for outpoint=e05b05e86a6d192645fa01365ef503b360d807d78575f0391e0d4aae326ea9af:1 at height=560846
2019-01-31 03:17:48.222 [INF] CNCT: *contractcourt.commitSweepResolver(e612b571044b5386d1c15babd701823ea164ab045a8a189552ea6739540c8d1b:1): waiting for commit output to be swept
2019-01-31 03:17:48.222 [INF] CNCT: *contractcourt.commitSweepResolver(e612b571044b5386d1c15babd701823ea164ab045a8a189552ea6739540c8d1b:1): commit output swept by txid=aacffe0e40b1fa256f80be27fb8479b6e4f456550fbd61cde1694b78ef40bed7
2019-01-31 03:17:48.342 [INF] CNCT: *contractcourt.commitSweepResolver(e612b571044b5386d1c15babd701823ea164ab045a8a189552ea6739540c8d1b:1): waiting for commit sweep txid=aacffe0e40b1fa256f80be27fb8479b6e4f456550fbd61cde1694b78ef40bed7 conf
2019-01-31 03:17:48.342 [INF] NTFN: New confirmation subscription: txid=aacffe0e40b1fa256f80be27fb8479b6e4f456550fbd61cde1694b78ef40bed7, num_confs=1
2019-01-31 03:17:48.451 [ERR] CNCT: unable to fetch contract resolutions: no contract resolutions exist
2019-01-31 03:17:48.451 [ERR] CNCT: ChannelArbitrator(f567819c8f9526d62ce2d14eea91a707fe713a4e18ae0ad89a0dd303aea9b836:0): unable to advance state: no contract resolutions exist
2019-01-31 03:17:48.451 [WRN] CNCT: ChannelArbitrator(f567819c8f9526d62ce2d14eea91a707fe713a4e18ae0ad89a0dd303aea9b836:0): detected closedchannel with no contract resolutions written.
2019-01-31 03:17:48.451 [INF] CNCT: ChannelArbitrator(048ba1a20e4c1c7c1e1915ecb2af7ec653c0aef4303c9bb2e1566d63034a409b:0): starting state=StateContractClosed
2019-01-31 03:17:48.511 [INF] NTFN: New confirmation subscription: txid=afe236d78af823288e79484d9bcf5368e97064e237eed6308f97edf903e5c117, num_confs=1
2019-01-31 03:17:48.537 [INF] NTFN: Dispatching 1 confirmation notification for txid=e0eb8dbca98a908d73f8f269bf53c0b67cb0eb09f76110de44f6b349352a1238
2019-01-31 03:17:48.537 [INF] CNCT: *contractcourt.htlcSuccessResolver(55932bb2f35fd5457cb1fa7c51d8f89ac8aa2163420b54e7f0509bdf1806f96e): waiting for sweep tx (txid=afe236d78af823288e79484d9bcf5368e97064e237eed6308f97edf903e5c117) to be confirmed
2019-01-31 03:17:48.537 [INF] NTFN: New spend subscription: spend_id=11, outpoint=e0eb8dbca98a908d73f8f269bf53c0b67cb0eb09f76110de44f6b349352a1238:0, height_hint=560698
2019-01-31 03:17:48.634 [ERR] CNCT: unable to fetch contract resolutions: no contract resolutions exist
2019-01-31 03:17:48.634 [ERR] CNCT: ChannelArbitrator(048ba1a20e4c1c7c1e1915ecb2af7ec653c0aef4303c9bb2e1566d63034a409b:0): unable to advance state: no contract resolutions exist
2019-01-31 03:17:48.634 [WRN] CNCT: ChannelArbitrator(048ba1a20e4c1c7c1e1915ecb2af7ec653c0aef4303c9bb2e1566d63034a409b:0): detected closedchannel with no contract resolutions written.
2019-01-31 03:17:48.634 [INF] CNCT: ChannelArbitrator(e09d8f55a50fe9a396e0f942eaee85e6ba870c72ffacae6f95b73d05d8a48404:0): starting state=StateContractClosed
2019-01-31 03:17:48.744 [INF] CNCT: *contractcourt.commitSweepResolver(f5c6598c5ad95bdd7335eeb2ec8f8cda4829d7bdb974447216edfc8f3c3df9ee:1): waiting for commit output to be swept
2019-01-31 03:17:49.148 [ERR] CNCT: unable to fetch contract resolutions: no contract resolutions exist
2019-01-31 03:17:49.148 [ERR] CNCT: ChannelArbitrator(e09d8f55a50fe9a396e0f942eaee85e6ba870c72ffacae6f95b73d05d8a48404:0): unable to advance state: no contract resolutions exist
2019-01-31 03:17:49.148 [WRN] CNCT: ChannelArbitrator(e09d8f55a50fe9a396e0f942eaee85e6ba870c72ffacae6f95b73d05d8a48404:0): detected closedchannel with no contract resolutions written.
2019-01-31 03:17:49.152 [INF] CNCT: ChannelArbitrator(3f68225091c048722233e4e4c315a974a4de25c3fdf3aea3878a8a95f5d1d95c:0): starting state=StateContractClosed
2019-01-31 03:17:49.153 [ERR] CNCT: unable to fetch contract resolutions: no contract resolutions exist
2019-01-31 03:17:49.153 [ERR] CNCT: ChannelArbitrator(3f68225091c048722233e4e4c315a974a4de25c3fdf3aea3878a8a95f5d1d95c:0): unable to advance state: no contract resolutions exist
2019-01-31 03:17:49.153 [WRN] CNCT: ChannelArbitrator(3f68225091c048722233e4e4c315a974a4de25c3fdf3aea3878a8a95f5d1d95c:0): detected closedchannel with no contract resolutions written.
2019-01-31 03:17:49.154 [INF] CNCT: ChannelArbitrator(e07afe293b20910363ad5b01bd7f0192f6bf88d385002e74ff8594bf29c4d888:1): starting state=StateWaitingFullResolution
2019-01-31 03:17:49.154 [INF] CNCT: ChannelArbitrator(e07afe293b20910363ad5b01bd7f0192f6bf88d385002e74ff8594bf29c4d888:1): still awaiting contract resolution
2019-01-31 03:17:49.155 [INF] CNCT: ChannelArbitrator(e07afe293b20910363ad5b01bd7f0192f6bf88d385002e74ff8594bf29c4d888:1): relaunching 1 contract resolvers
2019-01-31 03:17:49.155 [INF] NTFN: New confirmation subscription: txid=57addab6ccb2a6a1390367e02a1219f1a372e57295971193685459f4931af919, num_confs=1
2019-01-31 03:17:49.242 [INF] NTFN: Dispatching 1 confirmation notification for txid=bcec52500748200ed0848ddfad1e9ed30f7ae1c552c528bbd9da69d52a291f59
2019-01-31 03:17:49.311 [INF] DISC: Authenticated Gossiper is starting
2019-01-31 03:17:49.312 [INF] BRAR: Starting contract observer, watching for breaches.
2019-01-31 03:17:49.312 [INF] NTFN: New block epoch subscription
2019-01-31 03:17:49.340 [INF] NTFN: Dispatching 1 confirmation notification for txid=aacffe0e40b1fa256f80be27fb8479b6e4f456550fbd61cde1694b78ef40bed7
2019-01-31 03:17:49.340 [INF] CNCT: ChannelPoint(e612b571044b5386d1c15babd701823ea164ab045a8a189552ea6739540c8d1b:1) commit tx is fully resolved, at height: 560845
2019-01-31 03:17:49.340 [INF] CRTR: FilteredChainView starting
2019-01-31 03:17:49.340 [INF] NTFN: New spend subscription: spend_id=12, outpoint=bcec52500748200ed0848ddfad1e9ed30f7ae1c552c528bbd9da69d52a291f59:0, height_hint=542527
2019-01-31 03:17:49.340 [INF] CNCT: *contractcourt.commitSweepResolver(9cebba83a510e9b2d52bbaeb9986b9e57ba86ff7adec1310c6afda253334a408:0): waiting for commit output to be swept
2019-01-31 03:17:49.537 [INF] CNCT: ChannelArbitrator(e612b571044b5386d1c15babd701823ea164ab045a8a189552ea6739540c8d1b:1): a contract has been fully resolved!
2019-01-31 03:17:49.537 [INF] CNCT: ChannelArbitrator(e612b571044b5386d1c15babd701823ea164ab045a8a189552ea6739540c8d1b:1): all contracts fully resolved, exiting
2019-01-31 03:17:49.537 [INF] CNCT: Marking ChannelPoint(e612b571044b5386d1c15babd701823ea164ab045a8a189552ea6739540c8d1b:1) fully resolved
2019-01-31 03:17:49.539 [INF] CHDB: Pruning link node 031678745383bd273b4c3dbefc8ffbf4847d85c2f62d3407c0c980430b3257c403 with zero open channels from database
2019-01-31 03:17:49.737 [INF] NTFN: Cancelling epoch notification, epoch_id=9
2019-01-31 03:17:49.837 [INF] NTFN: Dispatching 1 confirmation notification for txid=57addab6ccb2a6a1390367e02a1219f1a372e57295971193685459f4931af919
2019-01-31 03:17:49.838 [INF] NTFN: New spend subscription: spend_id=13, outpoint=57addab6ccb2a6a1390367e02a1219f1a372e57295971193685459f4931af919:0, height_hint=560050
2019-01-31 03:17:49.838 [INF] CNCT: *contractcourt.commitSweepResolver(e07afe293b20910363ad5b01bd7f0192f6bf88d385002e74ff8594bf29c4d888:1): waiting for commit output to be swept
2019-01-31 03:17:54.241 [INF] CRTR: Filtering chain using 22505 channels active
2019-01-31 03:17:54.244 [INF] CRTR: Prune tip for Channel Graph: height=560844, hash=0000000000000000000d0f368af0d40d0d80dd0eacd6f35ade8cc4bdf8903134
2019-01-31 03:17:54.245 [INF] CRTR: Syncing channel graph from height=560844 (hash=0000000000000000000d0f368af0d40d0d80dd0eacd6f35ade8cc4bdf8903134) to height=560846 (hash=0000000000000000001d0f74f0c77011bccb4ac1a70bf76b34b4a81e76e97e5b)

I note that [ERR] CNCT: ChannelArbitrator(3f68225091c048722233e4e4c315a974a4de25c3fdf3aea3878a8a95f5d1d95c:0): unable to advance state: no contract resolutions exist errors are present. Not sure what that means...

joostjager commented 5 years ago

@Horndev It seems like this last run of lnd swept something: https://www.smartbit.com.au/tx/aacffe0e40b1fa256f80be27fb8479b6e4f456550fbd61cde1694b78ef40bed7

You can get more info in the log by setting the lnd log level to debug: lncli debuglevel --level=debug

Can you run it again with debug logs and also post the output from pendingchannels as it is now, marking which output is concerning? (for small and zero amounts it is expected behaviour that they remain pending until those can be grouped together to make the total tx have a positive yield)

The no contract resolutions exist error is a known issue which probably is no real bug.

joostjager commented 5 years ago

@sci4me can you do the same thing? Full lnd startup log at debug log level? And current output of pendingchannels?

Horndev commented 5 years ago

@joostjager That sweep is not one of the problem channels. See above that it did not have negative maturity when I first posted this issue.

{
            "channel": {
                "remote_node_pub": "031678745383bd273b4c3dbefc8ffbf4847d85c2f62d3407c0c980430b3257c403",
                "channel_point": "e612b571044b5386d1c15babd701823ea164ab045a8a189552ea6739540c8d1b:1",
                "capacity": "5000000",
                "local_balance": "2586729",
                "remote_balance": "0"
            },
            "closing_txid": "e05b05e86a6d192645fa01365ef503b360d807d78575f0391e0d4aae326ea9af",
            "limbo_balance": "2586729",
            "maturity_height": 560735,
            "blocks_til_maturity": 30,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        },

The problem force closes are those which show zero or negative maturity - they never get swept.

See, for example, https://www.smartbit.com.au/tx/15ea01435c9d6fc9433d581254c507e74a89a7b6c9572f048011996a94724517

which is from this channel with negative maturity:

{
            "channel": {
                "remote_node_pub": "03a96577e4cf8cac96937f4bf2753f7bd71323af5563690c8ed39c4e058c66c6c7",
                "channel_point": "5dfc4e79307094c0ce821d2c67bc89f0bb9e12d47546fa69218196bc6beb3f21:1",
                "capacity": "50000",
                "local_balance": "579",
                "remote_balance": "0"
            },
            "closing_txid": "15ea01435c9d6fc9433d581254c507e74a89a7b6c9572f048011996a94724517",
            "limbo_balance": "579",
            "maturity_height": 560282,
            "blocks_til_maturity": -423,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        },

The channel has closed to this address (https://www.smartbit.com.au/address/bc1ql3uut82z6cyeamg5csym5vz0flx283mrdzhpjrufc35fvcy7vhsqj3ytxh), which should have been swept long ago (even with the example you posted!)

Why is the sweeper not sweeping that address?

Also - what's going on with this channel: ?

{
            "channel": {
                "remote_node_pub": "03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f",
                "channel_point": "2a4683fed472f26b08e2567b46e99ab3e606ae2a1887e83cbaff82a7dc6af00c:0",
                "capacity": "2000000",
                "local_balance": "1468960",
                "remote_balance": "0"
            },
            "closing_txid": "e730488549fc7990f0e7ab72a7d8f2daefb6b89a97c5f77d673d1c1fbd5b3525",
            "limbo_balance": "0",
            "maturity_height": 0,
            "blocks_til_maturity": 0,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        },

Why does it show limbo balance 0? Were those funds lost? The closing_txid looks very strange to me.

ghost commented 5 years ago

I'm a little confused; I should have written down the wallet balance before because now the pending channels are empty. I think I got the funds back but I don't know; shouldn't I see something happen to the HTLC outpount on the blockchain? shrugs

Here's pendingchannels:

{
    "total_limbo_balance": "0",
    "pending_open_channels": [
    ],
    "pending_closing_channels": [
    ],
    "pending_force_closing_channels": [
    ],
    "waiting_close_channels": [
    ]
}

Having a little trouble with the log; can get it later if it's still needed.

Horndev commented 5 years ago

Ok, here is my LND debug trace on startup: lnd_dbg.log

I see that the transaction you posted shows up.

I see that the sweeper finds the channels (e.g.):

2019-01-31 18:20:33.921 [INF] SWPR: Sweep request received: out_point=bcec52500748200ed0848ddfad1e9ed30f7ae1c552c528bbd9da69d52a291f59:0, witness_type=CommitmentTimeLock, time_lock=144, size=0.00000602 BTC

and

2019-01-31 18:20:34.052 [DBG] SWPR: Wait for spend of bcec52500748200ed0848ddfad1e9ed30f7ae1c552c528bbd9da69d52a291f59:0

then I see

2019-01-31 18:20:35.414 [DBG] NTFN: Updating confirmation details for txid=bcec52500748200ed0848ddfad1e9ed30f7ae1c552c528bbd9da69d52a291f59
2019-01-31 18:20:35.494 [INF] NTFN: Dispatching 1 confirmation notification for txid=bcec52500748200ed0848ddfad1e9ed30f7ae1c552c528bbd9da69d52a291f59
2019-01-31 18:20:35.494 [DBG] NTFN: Using height hint 542527 retrieved from cache for outpoint=bcec52500748200ed0848ddfad1e9ed30f7ae1c552c528bbd9da69d52a291f59:0
2019-01-31 18:20:35.494 [INF] NTFN: New spend subscription: spend_id=5, outpoint=bcec52500748200ed0848ddfad1e9ed30f7ae1c552c528bbd9da69d52a291f59:0, height_hint=542527
2019-01-31 18:20:35.494 [DBG] NTFN: Attempting to dispatch spend for outpoint=bcec52500748200ed0848ddfad1e9ed30f7ae1c552c528bbd9da69d52a291f59:0 on registration since rescan has finished
2019-01-31 18:20:35.494 [INF] CNCT: *contractcourt.commitSweepResolver(9cebba83a510e9b2d52bbaeb9986b9e57ba86ff7adec1310c6afda253334a408:0): waiting for commit output to be swept

makes sense: https://www.smartbit.com.au/tx/bcec52500748200ed0848ddfad1e9ed30f7ae1c552c528bbd9da69d52a291f59

so I see for this channel:

2019-01-31 18:22:46.898 [INF] UTXN: NurseryReport: building nursery report for channel 9cebba83a510e9b2d52bbaeb9986b9e57ba86ff7adec1310c6afda253334a408:0

And then when I shut down:

2019-01-31 18:23:01.635 [ERR] CNCT: ChannelArbitrator(9cebba83a510e9b2d52bbaeb9986b9e57ba86ff7adec1310c6afda253334a408:0): unable to progress resolver: quitting
2019-01-31 18:23:01.635 [DBG] SWPR: Spend ntfn for bcec52500748200ed0848ddfad1e9ed30f7ae1c552c528bbd9da69d52a291f59:0 canceled
2019-01-31 18:23:01.635 [DBG] SWPR: Spend ntfn for 15ea01435c9d6fc9433d581254c507e74a89a7b6c9572f048011996a94724517:0 canceled
2019-01-31 18:23:01.635 [ERR] CNCT: ChannelArbitrator(39389828ccded50ad1d380ee0fc59c9f9fa7224f4fe6bfe2c58c6772592b34c8:1): unable to progress resolver: quitting
2019-01-31 18:23:01.635 [INF] HSWC: Block epoch canceled, decaying hash log shutting down
2019-01-31 18:23:01.635 [ERR] DISC: router has been shut down
2019-01-31 18:23:01.635 [ERR] CNCT: ChannelArbitrator(5dfc4e79307094c0ce821d2c67bc89f0bb9e12d47546fa69218196bc6beb3f21:1): unable to progress resolver: quitting
2019-01-31 18:23:01.635 [ERR] DISC: router has been shut down
2019-01-31 18:23:01.635 [ERR] DISC: router has been shut down
2019-01-31 18:23:01.635 [ERR] DISC: router has been shut down
2019-01-31 18:23:01.635 [ERR] DISC: router has been shut down
2019-01-31 18:23:01.635 [DBG] SWPR: Spend ntfn for 57addab6ccb2a6a1390367e02a1219f1a372e57295971193685459f4931af919:0 canceled
2019-01-31 18:23:01.635 [ERR] CNCT: ChannelArbitrator(e07afe293b20910363ad5b01bd7f0192f6bf88d385002e74ff8594bf29c4d888:1): unable to progress resolver: quitting
2019-01-31 18:23:01.635 [ERR] DISC: router has been shut down
2019-01-31 18:23:01.636 [ERR] DISC: router has been shut down
2019-01-31 18:23:02.103 [INF] HSWC: HTLC Switch shutting down
2019-01-31 18:23:02.103 [INF] UTXN: UTXO nursery shutting down
2019-01-31 18:23:02.103 [INF] BRAR: Breach arbiter shutting down
2019-01-31 18:23:02.103 [INF] DISC: Authenticated Gossiper is stopping
2019-01-31 18:23:02.103 [INF] CNCT: Stopping ChainArbitrator
2019-01-31 18:23:02.103 [DBG] CNCT: Stopping ChannelArbitrator(883f4b2cc4629d495bff2accca14d389b6e76e5174cb7ffe6fc3fd3f3ff4f111:0)
2019-01-31 18:23:02.103 [DBG] CNCT: Stopping ChannelArbitrator(54259ec27ef84973bb905611e5aa2b84f4a6ae40876c605cabfbb3545d4f33c1:0)
2019-01-31 18:23:02.103 [DBG] CNCT: Stopping ChannelArbitrator(2dcfbe36edb2c40d221356868ff415b3179deb3d39561a307a93f3307e83bebf:0)
2019-01-31 18:23:02.103 [DBG] CNCT: Stopping ChannelArbitrator(e07afe293b20910363ad5b01bd7f0192f6bf88d385002e74ff8594bf29c4d888:1)
2019-01-31 18:23:02.103 [DBG] CNCT: Stopping ChannelArbitrator(2a4683fed472f26b08e2567b46e99ab3e606ae2a1887e83cbaff82a7dc6af00c:0)
2019-01-31 18:23:02.103 [DBG] CNCT: Stopping ChannelArbitrator(e09d8f55a50fe9a396e0f942eaee85e6ba870c72ffacae6f95b73d05d8a48404:0)
2019-01-31 18:23:02.103 [DBG] CNCT: Stopping ChannelArbitrator(4a1d62d72c8848c58fb90f5235670436489b21aa22774789288f79e6a2b1c3aa:1)
2019-01-31 18:23:02.103 [DBG] CNCT: Stopping ChannelArbitrator(048ba1a20e4c1c7c1e1915ecb2af7ec653c0aef4303c9bb2e1566d63034a409b:0)
2019-01-31 18:23:02.103 [DBG] CNCT: Stopping ChannelArbitrator(3f68225091c048722233e4e4c315a974a4de25c3fdf3aea3878a8a95f5d1d95c:0)
2019-01-31 18:23:02.103 [DBG] CNCT: Stopping ChannelArbitrator(39389828ccded50ad1d380ee0fc59c9f9fa7224f4fe6bfe2c58c6772592b34c8:1)
2019-01-31 18:23:02.103 [DBG] CNCT: Stopping ChannelArbitrator(c51bab31943e3341429d89dd5f64b0b7ca66ab6326b9cde22737c52b56f9a6f5:1)
2019-01-31 18:23:02.103 [DBG] CNCT: Stopping ChannelArbitrator(8c6cc58b545ce59bfd24f91fdf683093851cad6dcb7fc1012176ef159158e839:1)
2019-01-31 18:23:02.103 [DBG] CNCT: Stopping ChannelArbitrator(9cebba83a510e9b2d52bbaeb9986b9e57ba86ff7adec1310c6afda253334a408:0)
2019-01-31 18:23:02.103 [DBG] CNCT: Stopping ChannelArbitrator(f567819c8f9526d62ce2d14eea91a707fe713a4e18ae0ad89a0dd303aea9b836:0)
2019-01-31 18:23:02.103 [DBG] CNCT: Stopping ChannelArbitrator(5dfc4e79307094c0ce821d2c67bc89f0bb9e12d47546fa69218196bc6beb3f21:1)
2019-01-31 18:23:02.103 [DBG] CNCT: Stopping ChannelArbitrator(f5c6598c5ad95bdd7335eeb2ec8f8cda4829d7bdb974447216edfc8f3c3df9ee:1)
2019-01-31 18:23:02.103 [DBG] SWPR: Sweeper shutting down
2019-01-31 18:23:02.103 [DBG] SWPR: Sweeper shut down

I can see these ChannelArbitrators which were active - but the channels are still never swept!

I don't understand why the channel never gets swept.

Horndev commented 5 years ago

I forgot to attach my latest pending channels: pending20190131.txt

thanks!

Roasbeef commented 5 years ago

@Horndev as explained above, the channels that show a negative blocks till maturity only have very small outputs. We cannot sweep an output of 500 satoshis by itself. The sweeper will avoid these outputs atm, since it's the case that we'll pay more in fees than the actual value of the output. In the future in order to reduce our UTXO set footprint, we'll start to sweep those.

Roasbeef commented 5 years ago

The only thing left to investigate is why the channels that show you having zero balance at the time of close, aren't being marked as fully closed in the database.

Horndev commented 5 years ago

@Roasbeef Yes - I understand that these are small, however, I have swept up 0.5 BTC in other closing channels (60+), including other "dust", while these remain unswept back to September 2018.

I strongly suspect there is something not working in the sweeper which is preventing these from being included in sweeps.

Roasbeef commented 5 years ago

The sweeper will avoid these outputs atm, since it's the case that we'll pay more in fees than the actual value of the output.

Horndev commented 5 years ago

@Roasbeef I have a hard time to believe that these would have more fees than the output. No way that the first one would be more than 42501 sat in fees (it is mature - close tx confirmed December 5 ) Or the one that is 1468960 satoshi with close tx confirmed June last year? Why is it not swept?

It can't just be the fees preventing the sweep.

Roasbeef commented 5 years ago
            "channel": {
                "remote_node_pub": "03a96577e4cf8cac96937f4bf2753f7bd71323af5563690c8ed39c4e058c66c6c7",
                "channel_point": "5dfc4e79307094c0ce821d2c67bc89f0bb9e12d47546fa69218196bc6beb3f21:1",
                "capacity": "50000",
                "local_balance": "579",
                "remote_balance": "0"
            },
            "closing_txid": "15ea01435c9d6fc9433d581254c507e74a89a7b6c9572f048011996a94724517",
            "limbo_balance": "579",
            "maturity_height": 560282,
            "blocks_til_maturity": -423,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]

579 satoshis is small. Too small to sweep by itself.

The second channel you ref has already been swept: https://www.smartbit.com.au/tx/0706a942a078e408d9bee90461f52fb0030528b63b0122be89454f9d7a96e432

Horndev commented 5 years ago

579 satoshis is small. Too small to sweep by itself.

I agree, so why was this"dust" not included in the sweep yesterday? https://www.smartbit.com.au/tx/aacffe0e40b1fa256f80be27fb8479b6e4f456550fbd61cde1694b78ef40bed7

and the other one I mention is:

{
            "channel": {
                "remote_node_pub": "03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f",
                "channel_point": "2a4683fed472f26b08e2567b46e99ab3e606ae2a1887e83cbaff82a7dc6af00c:0",
                "capacity": "2000000",
                "local_balance": "1468960",
                "remote_balance": "0"
            },
            "closing_txid": "e730488549fc7990f0e7ab72a7d8f2daefb6b89a97c5f77d673d1c1fbd5b3525",
            "limbo_balance": "0",
            "maturity_height": 0,
            "blocks_til_maturity": 0,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        },

If that was swept (good news?) why is it still showing up in pending channels?

Thanks for your help! I still think those small ones should have been swept.

Roasbeef commented 5 years ago

The sweeper will avoid these outputs atm, since it's the case that we'll pay more in fees than the actual value of the output.

We call this a negative yield output. We spend more than we earn to sweep it.

Horndev commented 5 years ago

Even at 1 sat per byte?

That aside - how can this one be a negative yield output?https://www.smartbit.com.au/address/bc1qpwszjpd767a7d5he7l07wpdkhh92v4mkja9wxx

That address should be swept. It's sitting there.

Roasbeef commented 5 years ago

Every new input adds to the size of a transaction. A fee must be paid based on the size. An input might add enough bytes to a transaction to the point that it cannot pay for the size increase it would incur.

Roasbeef commented 5 years ago

I won't repeat myself anymore on that front, I ask that you re-read all the responses, thanks!

Horndev commented 5 years ago

Well, I still think there is a bug somewhere in the sweeper, or some weird state here. I know how fees work - and I learned that you have some logic to check for "negative yield output" (makes sense).

I refuse to believe, however, that a sweep transaction will have fees more than 42501 satoshi given the small mempool, and it's not that large a transaction. Something is not working - shown by the unswept address I linked above (*9wxx). It's just not possible that the fee would be more than 42500 satoshi right now.

Could it be related to bitcoind? In the bitcoind log when LND starts up:

2019-01-31 03:17:46 FeeEst: 3 >60% decay 0.96200: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 1.0/(1.0 0 mem 0.0 out)
2019-01-31 03:17:46 FeeEst: 6 >85% decay 0.96200: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 1.0/(1.0 0 mem 0.0 out)
2019-01-31 03:17:46 FeeEst: 12 >95% decay 0.96200: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 1.0/(1.0 0 mem 0.0 out)
2019-01-31 03:17:46 FeeEst: 12 >95% decay 0.99520: feerate: -1 from (-1 - -1) -nan% 0.0/(0.0 0 mem 0.0 out) Fail: (0 - 1e+99) 100.00% 8.5/(8.5 0 mem 0.0 out)
2019-01-31 03:17:46 FeeEst: 12 >95% decay 0.99931: feerate: 10703.7 from (2925.26 - 1e+99) 99.26% 147.1/(148.2 0 mem 0.0 out) Fail: (0 - 2925.26) 98.33% 37.9/(38.5 0 mem 0.0 out)

I see some fee estimations and it looks buggy - nan% and feerates -1?

Horndev commented 5 years ago

Crazy thought: what if I patch the sweeper FeeEstimator, override it and return 2 sat per byte or something. Just to close out this node. I'm in no rush for the confirmation, and at least I could get the last of the funds out.

Roasbeef commented 5 years ago

Referring back to my _original message:

The final case in your report seems to be channels that have been closed with no coins on our side, but which are still showing up in pendingchannels (shows zero balance at time of close)

I'm counting those confirmed but not yet dispatched in that category (lack of confirmation dispatch).

Horndev commented 5 years ago

I pasted my entire pending channels, so maybe I'm not communicating this well. Seriously dude - sorry for dragging this all out with you. Once i'm fully convinced there's nothing wrong in LND I'll drop it.

I'm patching in some additional tracing for my own sanity in sweeper.go to see what's going on.

Let's focus on this channel:

{
            "channel": {
                "remote_node_pub": "03cb7983dc247f9f81a0fa2dfa3ce1c255365f7279c8dd143e086ca333df10e278",
                "channel_point": "e09d8f55a50fe9a396e0f942eaee85e6ba870c72ffacae6f95b73d05d8a48404:0",
                "capacity": "16777215",
                "local_balance": "42501",
                "remote_balance": "0"
            },
            "closing_txid": "1fdf0393254efd7bdb937c339a01ece4f67e0f601f17681b9519abeefed5eb6d",
            "limbo_balance": "0",
            "maturity_height": 0,
            "blocks_til_maturity": 0,
            "recovered_balance": "0",
            "pending_htlcs": [
            ]
        },

I see that confirmed a long time ago, it's mature, and ripe to sweep. I had 42501 satoshi local. Remote balance shows incorrectly as 0 - just see the closingtx.

The 42501 Satoshi are still sitting in an address, but have not been swept. I do not think this is related to fees, so something is going on.

Horndev commented 5 years ago

Wohoo! some small success:

https://www.smartbit.com.au/tx/604194da8766b70dc371c3f0d73f1b18195cdc464d4e12ba241d4253ac071ce9

I think something is still going on which I don't understand.

I suspect that the problem is that I was running bitcoind with --blocksonly, and that may be messing up the fee calculations. Yet, I'm still not sure why the 42501 sat output was not swept in.

So - it still didn't sweep everything, but progress was made :)

molxyz commented 5 years ago

@Horndev Right, you need to be patient. I've seen sweeper work very well but it takes time. I just saw that tx from reading your long posts and it's hard to read from all the long large blocks of text you have here.

Also, I'm wondering.. Did you close a bunch of channels months ago around June 2018 and then shut down your node didn't open it back up until lately?

Horndev commented 5 years ago

@molxyz Well, it wasn't patience required in this case. My node has been running 24x7 (except for upgrades) since around March last year. I did not shut it down. It is the node from https://www.coinpanic.com/Lightning/CommunityJar

I think it was the --blocksonly mode in bitcoind which screws up the fee calculations for LND. I'm not sure exactly where it goes wrong, however.

There is still an issue with the first closed channel in the list (and possibly others). I think the problem is related to these lines in the log:

2019-02-01 00:19:42.156 [INF] UTXN: NurseryReport: building nursery report for channel e09d8f55a50fe9a396e0f942eaee85e6ba870c72ffacae6f95b73d05d8a48404:0
2019-02-01 02:29:09.240 [DBG] CNCT: Starting ChannelArbitrator(e09d8f55a50fe9a396e0f942eaee85e6ba870c72ffacae6f95b73d05d8a48404:0), htlc_set=(contractcourt.htlcSet) {
2019-02-01 02:29:09.240 [INF] CNCT: ChannelArbitrator(e09d8f55a50fe9a396e0f942eaee85e6ba870c72ffacae6f95b73d05d8a48404:0): starting state=StateContractClosed
2019-02-01 02:29:09.242 [ERR] CNCT: ChannelArbitrator(e09d8f55a50fe9a396e0f942eaee85e6ba870c72ffacae6f95b73d05d8a48404:0): unable to advance state: no contract resolutions exist
2019-02-01 02:29:09.242 [WRN] CNCT: ChannelArbitrator(e09d8f55a50fe9a396e0f942eaee85e6ba870c72ffacae6f95b73d05d8a48404:0): detected closedchannel with no contract resolutions written.
2019-02-01 02:30:02.754 [INF] UTXN: NurseryReport: building nursery report for channel e09d8f55a50fe9a396e0f942eaee85e6ba870c72ffacae6f95b73d05d8a48404:0

It doesn't seem to ever make it to the sweeper in this case...

molxyz commented 5 years ago

@Horndev Wait.. you've been running your bitcoind with --blocksonly ? From my experience, that would make txs not broadcast.

Horndev commented 5 years ago

@molxyz It's been working just fine, up until now. It still broadcasts, just doesn't listen over BTC network (for unconfirmed txns).

Can you point to me where in the documentation it says not to do that?

molxyz commented 5 years ago

@Horndev https://bitcoin.org/en/full-node#blocks-only-mode

Horndev commented 5 years ago

@molxyz Yes, that's right, it doesn't forward over the BTC protocol, but still forwards from RPC calls (like from LND). It technically works, but I guess it can't estimate fees - see my log from bitcoind returning nan%, etc.

Since LND relies on this, I think it messes LND up. I suspect, LND falls back to a default fee and still works - usually.

molxyz commented 5 years ago

@Horndev I don't really know about how fee estimation is related to --blocksonly but i do know in 3 different cases that txs could not broadcast from bitcoin core wallet when the wallet was run with --blocksonly. I also know we've had issues with bitcoind wrt ZMQ notifications, this is why we're advised not to run more than two nodes on a same bitcoind node....

Hm.. I'm looking at your tx that has "local_balance": "42501", I'm wondering if you remove that --blocksonly can you send away this amount in another tx?

Horndev commented 5 years ago

@molxyz I suspect that bitcoind uses the mempool to calculate the fee, so no mempool, no way to calculate. My node broadcasted just fine in --blocksonly with whatever backup lnd had for fee estimation. The smaller utxos, however, were not being swept with that on. I have removed --blocksonly and that's when they finally got swept.

As for the the "local_balance": "42501" you mention, see the errors I recently posted about the Contract Court. That utxo never even gets sent to the sweeper for input, so I don't know how to get that one to sweep.

molxyz commented 5 years ago

@Horndev Hmmm yes it seems for some reason the amount 42501 sat is not in your lnd wallet... I'm not sure what to think of it except I suspect we still have issues with ZMQ. There's this PR to improve ZMQ which got merged into bitcoin core master and probably will be in version 0.18.0: https://github.com/bitcoin/bitcoin/pull/14060 so hopefully it will help in the future.

Horndev commented 5 years ago

@molxyz Thanks - So any idea how to get it swept?

wpaulino commented 5 years ago

@Horndev I'm afraid the channel e09d8f55a50fe9a396e0f942eaee85e6ba870c72ffacae6f95b73d05d8a48404 won't be able to be swept. There was a previous race condition in lnd that would cause us to not store some information required to successfully sweep a channel after restarts. This has been fixed, but it looks like you ran into this bug, so there's not much we can do on our end.

Horndev commented 5 years ago

@wpaulino Thanks for that info. Darn. I guess this is a badge of honor then! It's the reckless early adopter burn.

I have a few channels stuck like this, so I assume they are all lost then.

wpaulino commented 5 years ago

Gotcha, in that case I'll go ahead and close this for now. Feel free to re-open if you believe you've run into another issue.