Nodes not mining and -1 in synced headers and synced blocks

+3 votes
Hello,

I checked the getpeerinfo command on a blockchain running from past 8 months I found the synced blocks and synced headers of one of the peers is -1 and the another peer is not syncing the mempool. The mining seems to have paused as well, leaving a lot of transactions in the mempool which are not being mined and synced.

 {
        "id" : 16,
        "addr" : "10.0.4.238:57148",
        "addrlocal" : "11.0.2.19:6004",
        "services" : "0000000000000001",
        "lastsend" : 1606634315,
        "lastrecv" : 1606634315,
        "bytessent" : 64775843,
        "bytesrecv" : 58707709,
        "conntime" : 1597433750,
        "pingtime" : 0.036274,
        "version" : 70002,
        "subver" : "/MultiChain:0.2.0.10/",
        "handshakelocal" : "1K73Tko1w9ZVPaSL5L5RHFEBnbNVWTHB5c8owZ",
        "handshake" : "1WmQoWUM5GjErTH1KnjQjDSThGEFapx6GMqTGQ",
        "inbound" : true,
        "startingheight" : 6738,
        "banscore" : 0,
        "synced_headers" : -1,
        "synced_blocks" : -1,
        "inflight" : [
        ],
        "whitelisted" : false
    },
    {
        "id" : 17,
        "addr" : "10.0.2.218:41652",
        "addrlocal" : "11.0.2.19:6004",
        "services" : "0000000000000001",
        "lastsend" : 1606634313,
        "lastrecv" : 1606634313,
        "bytessent" : 6121210,
        "bytesrecv" : 54235,
        "conntime" : 1606633541,
        "pingtime" : 0.078501,
        "version" : 70002,
        "subver" : "/MultiChain:0.2.0.10/",
        "handshakelocal" : "1K73Tko1w9ZVPaSL5L5RHFEBnbNVWTHB5c8owZ",
        "handshake" : "1UgYYerpfmaV5R1sMpWSci6ymP4HD25G2FPHAs",
        "inbound" : true,
        "startingheight" : 6738,
        "banscore" : 0,
        "synced_headers" : -1,
        "synced_blocks" : -1,
        "inflight" : [
        ],
        "whitelisted" : false
    }

 

There are a lot of transactions in the mempool of this node which are not getting cleared, the debug.log ends up with

 

2020-11-29 07:32:08 MultiChainMiner: Block Found - 00bae732a4e336dce3d98613735b74d0cf3f9ccd74a166313bffa2972b556713, prev: 00ede3b542cf0a2ec323bbb547fe7d7c58e56e1969f11970c8f118395e914428, height: 6739, txs: 1312
2020-11-29 07:32:08 VerifyBlockMiner: Permission denied for miner 1K73Tko1w9ZVPaSL5L5RHFEBnbNVWTHB5c8owZ received in block signature
2020-11-29 07:32:08 VerifyBlockMiner: Block 00bae732a4e336dce3d98613735b74d0cf3f9ccd74a166313bffa2972b556713 (height 6739) miner verification failed
2020-11-29 07:32:08 ERROR: ProcessNewBlock : AcceptBlock FAILED
2020-11-29 07:32:08 ERROR: MultiChainMiner : ProcessNewBlock, block not accepted
2020-11-29 07:32:10 MultiChainMiner: Block Found - 00eae7e02fe799d07e969164b2b098573d6da5efa11d362483fcd007aa71b740, prev: 00ede3b542cf0a2ec323bbb547fe7d7c58e56e1969f11970c8f118395e914428, height: 6739, txs: 1312
2020-11-29 07:32:11 VerifyBlockMiner: Permission denied for miner 1K73Tko1w9ZVPaSL5L5RHFEBnbNVWTHB5c8owZ received in block signature
2020-11-29 07:32:11 VerifyBlockMiner: Block 00eae7e02fe799d07e969164b2b098573d6da5efa11d362483fcd007aa71b740 (height 6739) miner verification failed
2020-11-29 07:32:11 ERROR: ProcessNewBlock : AcceptBlock FAILED
2020-11-29 07:32:11 ERROR: MultiChainMiner : ProcessNewBlock, block not accepted

all the three nodes have mining permission, with mining diversity set to 0.66.

Tried stopping and restarting the nodes except the one with mempool, but nothing different happened.

 

Thank You
asked Nov 29, 2020 by DarkBlaze
edited Nov 29, 2020 by DarkBlaze
Quick question: are you using transaction filters?
No, not using any transaction filter
Can you please:
1. Send us the output of

listblocks -5
listpermissions mine * true    
getinfo
getblockchainparams
getpeerinfo (if it is different from what you already sent)
getmempoolinfo

2. Make sure other nodes with mining permission are running and you don't see similar "Permission denied" messages there. Please also make sure getpeerinfo is not empty on those nodes and  getmempoolinfo output is identical to what you see on the node with mempool.
Hi Michael,

getpeerinfo and getmempoolinfo have different outputs on the three nodes. The first node is where most of the transactions are being sent and that is where the mempool is accumulating, unable to sync with other two nodes. This is constantly putting pressure on the server's memory increasing the risk of it becoming unresponsive - something that we would definitely like to avoid.

for the first node 11.0.2.19

getpeerinfo

[
    {
        "id" : 17,
        "addr" : "10.0.2.218:41652",
        "addrlocal" : "11.0.2.19:6004",
        "services" : "0000000000000001",
        "lastsend" : 1606770037,
        "lastrecv" : 1606770037,
        "bytessent" : 7136763,
        "bytesrecv" : 921957,
        "conntime" : 1606633541,
        "pingtime" : 0.035137,
        "pingwait" : 2.36775,
        "version" : 70002,
        "subver" : "/MultiChain:0.2.0.10/",
        "handshakelocal" : "1K73Tko1w9ZVPaSL5L5RHFEBnbNVWTHB5c8owZ",
        "handshake" : "1UgYYerpfmaV5R1sMpWSci6ymP4HD25G2FPHAs",
        "inbound" : true,
        "startingheight" : 6738,
        "banscore" : 0,
        "synced_headers" : -1,
        "synced_blocks" : -1,
        "inflight" : [
        ],
        "whitelisted" : false
    },
    {
        "id" : 18,
        "addr" : "10.0.4.238:41912",
        "addrlocal" : "11.0.2.19:6004",
        "services" : "0000000000000001",
        "lastsend" : 1606770030,
        "lastrecv" : 1606770030,
        "bytessent" : 7122448,
        "bytesrecv" : 908338,
        "conntime" : 1606635575,
        "pingtime" : 0.06566,
        "version" : 70002,
        "subver" : "/MultiChain:0.2.0.10/",
        "handshakelocal" : "1K73Tko1w9ZVPaSL5L5RHFEBnbNVWTHB5c8owZ",
        "handshake" : "1WmQoWUM5GjErTH1KnjQjDSThGEFapx6GMqTGQ",
        "inbound" : true,
        "startingheight" : 6738,
        "banscore" : 0,
        "synced_headers" : -1,
        "synced_blocks" : -1,
        "inflight" : [
        ],
        "whitelisted" : false
    }
]

getmempoolinfo

{
    "size" : 1374,
    "bytes" : 6181824
}

 

---------------------------------------------

for the second node 10.0.4.238

[
    {
        "id" : 1,
        "addr" : "11.0.2.19:6004",
        "addrlocal" : "10.0.4.238:41912",
        "services" : "0000000000000001",
        "lastsend" : 1606770143,
        "lastrecv" : 1606770143,
        "bytessent" : 910546,
        "bytesrecv" : 7124656,
        "conntime" : 1606635340,
        "pingtime" : 0.083819,
        "version" : 70002,
        "subver" : "/MultiChain:0.2.0.10/",
        "handshakelocal" : "1WmQoWUM5GjErTH1KnjQjDSThGEFapx6GMqTGQ",
        "handshake" : "1K73Tko1w9ZVPaSL5L5RHFEBnbNVWTHB5c8owZ",
        "inbound" : false,
        "startingheight" : 6738,
        "banscore" : 0,
        "synced_headers" : 6738,
        "synced_blocks" : 6738,
        "inflight" : [
        ],
        "whitelisted" : false
    },
    {
        "id" : 2,
        "addr" : "10.0.2.218:6004",
        "addrlocal" : "10.0.4.238:56270",
        "services" : "0000000000000001",
        "lastsend" : 1606770145,
        "lastrecv" : 1606770145,
        "bytessent" : 862398,
        "bytesrecv" : 862148,
        "conntime" : 1606635340,
        "pingtime" : 0.041019,
        "version" : 70002,
        "subver" : "/MultiChain:0.2.0.10/",
        "handshakelocal" : "1WmQoWUM5GjErTH1KnjQjDSThGEFapx6GMqTGQ",
        "handshake" : "1UgYYerpfmaV5R1sMpWSci6ymP4HD25G2FPHAs",
        "inbound" : false,
        "startingheight" : 6738,
        "banscore" : 0,
        "synced_headers" : -1,
        "synced_blocks" : -1,
        "inflight" : [
        ],
        "whitelisted" : false
    }
]

getmempoolinfo

{
    "size" : 9,
    "bytes" : 4056
}

---------------------------------------

for the third node 10.0.2.218

[
    {
        "id" : 1,
        "addr" : "11.0.2.19:6004",
        "addrlocal" : "10.0.2.218:41652",
        "services" : "0000000000000001",
        "lastsend" : 1606770391,
        "lastrecv" : 1606770391,
        "bytessent" : 924837,
        "bytesrecv" : 7139643,
        "conntime" : 1606633441,
        "pingtime" : 0.320203,
        "version" : 70002,
        "subver" : "/MultiChain:0.2.0.10/",
        "handshakelocal" : "1UgYYerpfmaV5R1sMpWSci6ymP4HD25G2FPHAs",
        "handshake" : "1K73Tko1w9ZVPaSL5L5RHFEBnbNVWTHB5c8owZ",
        "inbound" : false,
        "startingheight" : 6738,
        "banscore" : 0,
        "synced_headers" : 6738,
        "synced_blocks" : 6738,
        "inflight" : [
        ],
        "whitelisted" : false
    },
    {
        "id" : 3,
        "addr" : "10.0.4.238:56270",
        "addrlocal" : "10.0.2.218:6004",
        "services" : "0000000000000001",
        "lastsend" : 1606770391,
        "lastrecv" : 1606770391,
        "bytessent" : 862852,
        "bytesrecv" : 863102,
        "conntime" : 1606635475,
        "pingtime" : 0.00345,
        "version" : 70002,
        "subver" : "/MultiChain:0.2.0.10/",
        "handshakelocal" : "1UgYYerpfmaV5R1sMpWSci6ymP4HD25G2FPHAs",
        "handshake" : "1WmQoWUM5GjErTH1KnjQjDSThGEFapx6GMqTGQ",
        "inbound" : true,
        "startingheight" : 6738,
        "banscore" : 0,
        "synced_headers" : -1,
        "synced_blocks" : -1,
        "inflight" : [
        ],
        "whitelisted" : false
    }
]

getmempoolinfo

{
    "size" : 9,
    "bytes" : 4056
}
Outputs for other APIs are given below from the first node. These are sensitive production workloads so I have masked certain info like chain name.

listblocks -5

[
    {
        "hash" : "00321ce6f5d0576dc8b28b009da8ed9b6009cd46bd943b82fc389807b59ea88b",
        "miner" : "1K73Tko1w9ZVPaSL5L5RHFEBnbNVWTHB5c8owZ",
        "confirmations" : 5,
        "height" : 6734,
        "time" : 1593041836,
        "txcount" : 1
    },
    {
        "hash" : "00c6fef1a0ce6e214d442e0b722f7f5d5bf406a04a3eee24019b905c3c8e2234",
        "miner" : "1WmQoWUM5GjErTH1KnjQjDSThGEFapx6GMqTGQ",
        "confirmations" : 4,
        "height" : 6735,
        "time" : 1593041687,
        "txcount" : 1
    },
    {
        "hash" : "00c29801647f01448bcd592d7c46e5b8daa17a4426b949fdcdd30a7145ab2cd5",
        "miner" : "1b2Sn4sfWwXJammXTqoAkAkB5ssQfPBHdov3zR",
        "confirmations" : 3,
        "height" : 6736,
        "time" : 1593041787,
        "txcount" : 1
    },
    {
        "hash" : "008e2a3a6b0622aafbbf57ba450a9e8e3b8761232bf1c48dd4c970fd07246611",
        "miner" : "1K73Tko1w9ZVPaSL5L5RHFEBnbNVWTHB5c8owZ",
        "confirmations" : 2,
        "height" : 6737,
        "time" : 1593041888,
        "txcount" : 1
    },
    {
        "hash" : "00ede3b542cf0a2ec323bbb547fe7d7c58e56e1969f11970c8f118395e914428",
        "miner" : "1WmQoWUM5GjErTH1KnjQjDSThGEFapx6GMqTGQ",
        "confirmations" : 1,
        "height" : 6738,
        "time" : 1595170815,
        "txcount" : 550
    }
]

---------

listpermissions mine * true

[
    {
        "address" : "1K73Tko1w9ZVPaSL5L5RHFEBnbNVWTHB5c8owZ",
        "for" : null,
        "type" : "mine",
        "startblock" : 0,
        "endblock" : 4294967295,
        "admins" : [
            "1K73Tko1w9ZVPaSL5L5RHFEBnbNVWTHB5c8owZ"
        ],
        "pending" : [
        ]
    },
    {
        "address" : "1WmQoWUM5GjErTH1KnjQjDSThGEFapx6GMqTGQ",
        "for" : null,
        "type" : "mine",
        "startblock" : 0,
        "endblock" : 4294967295,
        "admins" : [
            "1K73Tko1w9ZVPaSL5L5RHFEBnbNVWTHB5c8owZ"
        ],
        "pending" : [
        ]
    },
    {
        "address" : "1UgYYerpfmaV5R1sMpWSci6ymP4HD25G2FPHAs",
        "for" : null,
        "type" : "mine",
        "startblock" : 0,
        "endblock" : 4294967295,
        "admins" : [
            "1K73Tko1w9ZVPaSL5L5RHFEBnbNVWTHB5c8owZ"
        ],
        "pending" : [
        ]
    }
]

---------

getinfo

{
    "version" : "2.0.2",
    "nodeversion" : 20002901,
    "protocolversion" : 20010,
    "chainname" : "***",
    "description" : "MultiChain ***",
    "protocol" : "multichain",
    "port" : 6004,
    "setupblocks" : 60,
    "nodeaddress" : "***@11.0.2.19:6004",
    "burnaddress" : "1XXXXXXXXNXXXXXX6eXXXXXXKXXXXXXXZe2Rik",
    "incomingpaused" : false,
    "miningpaused" : false,
    "offchainpaused" : false,
    "walletversion" : 60000,
    "balance" : 0,
    "walletdbversion" : 3,
    "reindex" : false,
    "blocks" : 6738,
    "timeoffset" : 0,
    "connections" : 2,
    "proxy" : "",
    "difficulty" : 5.96046447753906e-8,
    "testnet" : false,
    "keypoololdest" : 1585048706,
    "keypoolsize" : 2,
    "paytxfee" : 0,
    "relayfee" : 0,
    "errors" : ""
}

---------

getblockchainparams

{
    "chain-protocol" : "multichain",
    "chain-description" : "MultiChain ***",
    "root-stream-name" : "root",
    "root-stream-open" : true,
    "chain-is-testnet" : false,
    "target-block-time" : 15,
    "maximum-block-size" : 8388608,
    "maximum-chunk-size" : 1048576,
    "maximum-chunk-count" : 1024,
    "default-network-port" : 6004,
    "default-rpc-port" : 7004,
    "anyone-can-connect" : false,
    "anyone-can-send" : false,
    "anyone-can-receive" : false,
    "anyone-can-receive-empty" : true,
    "anyone-can-create" : false,
    "anyone-can-issue" : false,
    "anyone-can-mine" : false,
    "anyone-can-activate" : false,
    "anyone-can-admin" : false,
    "support-miner-precheck" : true,
    "allow-arbitrary-outputs" : false,
    "allow-p2sh-outputs" : true,
    "allow-multisig-outputs" : true,
    "setup-first-blocks" : 60,
    "mining-diversity" : 0.66,
    "admin-consensus-upgrade" : 0.5,
    "admin-consensus-txfilter" : 0.5,
    "admin-consensus-admin" : 0.5,
    "admin-consensus-activate" : 0.5,
    "admin-consensus-mine" : 0.5,
    "admin-consensus-create" : 0,
    "admin-consensus-issue" : 0,
    "lock-admin-mine-rounds" : 10,
    "mining-requires-peers" : true,
    "mine-empty-rounds" : 10,
    "mining-turnover" : 0.5,
    "first-block-reward" : -1,
    "initial-block-reward" : 0,
    "reward-halving-interval" : 52560000,
    "reward-spendable-delay" : 1,
    "minimum-per-output" : 0,
    "maximum-per-output" : 100000000000000,
    "minimum-offchain-fee" : 0,
    "minimum-relay-fee" : 0,
    "native-currency-multiple" : 100000000,
    "skip-pow-check" : false,
    "pow-minimum-bits" : 8,
    "target-adjust-freq" : -1,
    "allow-min-difficulty-blocks" : false,
    "only-accept-std-txs" : true,
    "max-std-tx-size" : 4194304,
    "max-std-op-returns-count" : 1024,
    "max-std-op-return-size" : 2097152,
    "max-std-op-drops-count" : 5,
    "max-std-element-size" : 40000,
    "chain-name" : "***",
    "protocol-version" : 20010,
    "network-message-start" : "f2cbebfc",
    "address-pubkeyhash-version" : "00ea080e",
    "address-scripthash-version" : "05d6e41c",
    "private-key-version" : "80bb4fb2",
    "address-checksum-value" : "596503ca",
    "genesis-pubkey" : "02fe43768d2319716bfb0e69a81e7f4d069cd4933254f820b112421581fec2d0ff",
    "genesis-version" : 1,
    "genesis-timestamp" : 1585048706,
    "genesis-nbits" : 536936447,
    "genesis-nonce" : 6,
    "genesis-pubkey-hash" : "85f3946ac9cc01c5699c3a9b24323ce5736120f3",
    "genesis-hash" : "00e14393f3c901f6ae946629e186d189675c55deb4741d43019ef8232f1831b5",
    "chain-params-hash" : "84ab487c0a932fecd70580343a61c2a52866a5cedd73f640dad2846658fd1c98"
}

1 Answer

0 votes

First, you should not worry about your in-memory transactions, the transactions send from specific node are backed on the disk. If you restart the node, they will refill the mempool (but you don't have to do this right now).

Second, you may resend these transactions to other nodes using resendwallettransactions API. But this will not resolve mining problem, it will just make them available there. Also, they are not stored on disk by those nodes until confirmed in block.

Third, it looks like mining stopped because you have more than 3 miners in the chain - and these miners are not what you see in the output of listpermissions. For the address to have mining permission, its grant should be confirmed in block. But listpermissions shows the state including unconfirmed transactions, which is obviously misleading - we will think how to improve this in the next version.

It looks like you have at least 4 miners in the chain:

1K73Tko1w9ZVPaSL5L5RHFEBnbNVWTHB5c8owZ and 1WmQoWUM5GjErTH1KnjQjDSThGEFapx6GMqTGQ are OK, but they cannot mine because of diversity.

But 1b2Sn4sfWwXJammXTqoAkAkB5ssQfPBHdov3zR and probably some other node we cannot currently see in the output of APIs (but it is not 1UgYYerpfmaV5R1sMpWSci6ymP4HD25G2FPHAs) are the miners which should mine the next block, but they are probably down.

(if you examine carefully the mempool of the first node, you are likely to find there two "revoke" transactions for 1b2Sn4sfWwXJammXTqoAkAkB5ssQfPBHdov3zR and another address and one "grant" for 1UgYYerpfmaV5R1sMpWSci6ymP4HD25G2FPHAs - you don't have to do this now)

And finally, why the first node tries to mine the block when it can't (and you see error messages in the log) - this is the bug we already fixed in the latest version. But it is not critical bug, you may ignore it, so you should not even upgrade MultiChain because of this.
 
The simplest solution is to bring back (at least temporarily) the node with address 1b2Sn4sfWwXJammXTqoAkAkB5ssQfPBHdov3zR or that miner with unknown address. If it is possible, after you bring up this node, make sure it is connected to other nodes and then call resendwallettransactions from these nodes. Then wait until mining is restarted and getmempoolinfo output shows 0. After that, you may stop that node(s).
 
If this doesn't work for you for some reason (you don't have private key for 1b2Sn4sfWwXJammXTqoAkAkB5ssQfPBHdov3zR or you don't remember exactly what was that "other" address), please let us know and we'll look for another solution. In this case I have to know who are the admins, i.e. we need the output of
 
listpermissions admin * true
 
 
answered Dec 1, 2020 by Michael
Hi Michael,

Appreciate the comprehensive answer. It really helped us understand the problem better.

We had upgraded the machine for one node in June. The new address 1UgYYerpfmaV5R1sMpWSci6ymP4HD25G2FPHAs was granted mining permission but it was never confirmed.

Currently, there are four mining addresses, two working and two frozen:

Working:
1K73Tko1w9ZVPaSL5L5RHFEBnbNVWTHB5c8owZ
1WmQoWUM5GjErTH1KnjQjDSThGEFapx6GMqTGQ

Frozen:
17aMjEtdoWigUqvjqhnw6oG5EH7ZNiVNACUkRn
1b2Sn4sfWwXJammXTqoAkAkB5ssQfPBHdov3zR

We were able to retrieve private key of 1b2Sn4sfWwXJammXTqoAkAkB5ssQfPBHdov3zR from backups.

If we attempt the solution suggested, setup a new node and import this address there, it still wont have a hot private key in the new node for mining.

Could you kindly advise on how to import the adresss with private key in the new node.
Or I can simply restore the backup folder on the new node? It already has the private key. Does that sound good?
* Or I can simply restore the backup folder on the new node? It already has the private key. Does that sound good?

If you backed up entire directory, it is indeed the simplest solution.

If this doesn't work, you may create new node, wait for it to sync with other nodes (i.e. have output of getblockcount  6738) and then use importprivkey API.
Please note, if the node which made those revoke/grant transactions is that with address  1K73Tko1w9ZVPaSL5L5RHFEBnbNVWTHB5c8owZ or 1WmQoWUM5GjErTH1KnjQjDSThGEFapx6GMqTGQ (other miners), the mining should be fixed automatically. But if is some other node, you may want to call resendwallettransactions from that node.
Hi Michael,

all the revoke/grant transaction were done by  1K73Tko1w9ZVPaSL5L5RHFEBnbNVWTHB5c8owZ

after doing all the steps of connecting the node with the address  1b2Sn4sfWwXJammXTqoAkAkB5ssQfPBHdov3zR to the blockchain, the nodes with the address 1K73Tko1w9ZVPaSL5L5RHFEBnbNVWTHB5c8owZ and  1UgYYerpfmaV5R1sMpWSci6ymP4HD25G2FPHA segfaulted when resendwallettransactions was run on the node.

*** Error in `multichaind': malloc(): smallbin double linked list corrupted: 0x000000000441b9b0 ***
======= Backtrace: =========
[0x15793f1]
[0x15843eb]
[0x1585e71]
[0x14583a8]

.............................
7ffd2d982000-7ffd2d984000 r-xp 00000000 00:00 0                          [vdso]
ffffffffff600000-ffffffffff601000 r-xp 00000000 00:00 0                  [vsyscall]
Segmentation fault (core dumped)
OK, this may be related to one of the bugs we fixed in one of the versions. You should restart these nodes, of course.

But is the mining problem resolved when you connected the node with address 1b2Sn4sfWwXJammXTqoAkAkB5ssQfPBHdov3zR?

Did you pass block 6738? You don't have to run resendwallettransactions transactions. Even if 1b2Sn4sfWwXJammXTqoAkAkB5ssQfPBHdov3zR will not have those transactions and mine empty block, this will release 1K73Tko1w9ZVPaSL5L5RHFEBnbNVWTHB5c8owZ from diversity constraint and it will confirm these transaction by itself.
No, the mining problem was not solved, even after connecting  1b2Sn4sfWwXJammXTqoAkAkB5ssQfPBHdov3zR and waiting for 10 minutes. Now 1K73Tko1w9ZVPaSL5L5RHFEBnbNVWTHB5c8owZ node has segfaulted and doesn't start it segfaults everytime when started with multichaind.
The mining problem will not be resolved until you successfully restart 1K73Tko1w9ZVPaSL5L5RHFEBnbNVWTHB5c8owZ.

Can you please try to restart it with -debug=mchn -debug=wallet options and send us 100 last lines of debug.log
...