Privacy: Restart caused by insufficient memory can cause inconsistent private state

[pinges]

Tasks:

• Deploy updated Orion and Besu to test network
• Rerun test scripts and validate changes

While running reorg testing with six besu/orion clients the following happened on two of the machines causing the state on that machine to become inconsistent with the rest of the members of the privacy group:

Besu Log:
{"timestamp":"2020-06-14T02:11:30,248","level":"INFO","thread":"EthScheduler-Workers-1","class":"BlockPropagationManager","message":"Imported #8,088,448 / 4 tx / 0 om / 4,475,388 (55.9%) gas / (0xa8f49cdc62fcf7de79b42d46ffcb89cbaafd8656dcc112fb9fd39c8b792c1373) in 0.903s. Peers: 39","throwable":""}
{"timestamp":"2020-06-14T02:13:18,932","level":"INFO","thread":"nioEventLoopGroup-3-1","class":"BlockPropagationManager","message":"Saving announced block 8088450 (0x8ae8ca9866c1e626933fb4828ab9c8775afae74dc7c577e9e5b16a401178e839) for future import","throwable":""}
{"timestamp":"2020-06-14T02:15:05,908","level":"INFO","thread":"nioEventLoopGroup-3-1","class":"BlockPropagationManager","message":"Saving announced block 8088451
.
.
.
{"timestamp":"2020-06-14T02:15:09,286","level":"INFO","thread":"nioEventLoopGroup-3-5","class":"BlockPropagationManager","message":"Saving announced block 8088463 (0x2352f8e831f2a2a13dcb4e70f3ffaefb05ff8e09cdafdc1de40d12affe80461a) for future import","throwable":""}
{"timestamp":"2020-06-14T02:15:09,300","level":"INFO","thread":"nioEventLoopGroup-3-5","class":"BlockPropagationManager","message":"Saving announced block 8088464 (0x207de6caace4575bb29e75b98801e53d321750a9e63b0f1d323938cbb708eab8) for future import","throwable":""}
OpenJDK 64-Bit Server VM warning: INFO: os::commit_memory(0x00000000e6c00000, 90177536, 0) failed; error='Not enough space' (errno=12)
[thread 21178 also had an error]
[thread 21183 also had an error]
[thread 21192 also had an error]
[thread 21257 also had an error]
[thread 21127 also had an error]
[thread 21117 also had an error]

There is insufficient memory for the Java Runtime Environment to continue.

Native memory allocation (mmap) failed to map 90177536 bytes for committing reserved memory.

An error report file with more information is saved as:

/tmp/hs_err_pid21038.log

[thread 21179 also had an error]
[thread 21181 also had an error]
Recording 1 scheduled to start in 15 s.

Use jcmd 30545 JFR.dump name=1 to copy recording data to file.
Setting logging level to INFO
{"timestamp":"2020-06-14T02:15:33,476","level":"INFO","thread":"main","class":"AltBN128PairingPrecompiledContract","message":"Using native alt bn128","throwable":""}
{"timestamp":"2020-06-14T02:15:34,447","level":"INFO","thread":"main","class":"SECP256K1","message":"Using native secp256k1","throwable":""}
.
.
.
{"timestamp":"2020-06-14T02:15:56,154","level":"INFO","thread":"nioEventLoopGroup-3-4","class":"FullSyncTargetManager","message":"No sync target, waiting for peers: 1","throwable":""}
{"timestamp":"2020-06-14T02:15:57,949","level":"INFO","thread":"nioEventLoopGroup-3-4","class":"SyncTargetManager","message":"Found common ancestor with peer 0x936ac2bf0b816350eb... at block 8088448","throwable":""}
{"timestamp":"2020-06-14T02:16:07,093","level":"INFO","thread":"nioEventLoopGroup-3-4","class":"BlockPropagationManager","message":"Saving announced block 8088467 (0xd9c239e06ffedcc87005f3d4ac06513260baf3206a21a1585b9f38ef4c7da36f) for future import","throwable":""}
{"timestamp":"2020-06-14T02:16:08,486","level":"INFO","thread":"nioEventLoopGroup-3-6","class":"BlockPropagationManager","message":"Saving announced block 8088466 (0x11fa862f07df203a8a5e39b100ba21d80900f591c8a1c8930f5322fdeddc56e2) for future import","throwable":""}
{"timestamp":"2020-06-14T02:16:12,404","level":"ERROR","thread":"EthScheduler-Services-5 (importBlock)","class":"PrivacyPrecompiledContract","message":"Failed to process private transaction 0x74c37eb6c8d172ca6a41420ffbb963f848ae92eb6aaa28e85bfcaffcb4b429d5: Private Transaction nonce 0, is lower than sender account nonce 1.","throwable":""}
{"timestamp":"2020-06-14T02:16:41,452","level":"INFO","thread":"EthScheduler-Workers-1","class":"BlockPropagationManager","message":"Imported 1 pending blocks","throwable":""}

[pinges]

The private transactions used for testing are calling the xor fuction on the following contract:

contract ReorgTest {
event stored(address _to, uint _amount);
uint _value;
function xor(uint _input) public returns (uint) {
uint _tmp = _value;
_value ^= _input;
emit xored(msg.sender, _input, _value, _tmp, block.number, blockhash(block.number - 1));
}
function value() view public returns (uint) {
return _value;
}
event xored(address sender, uint input, uint newValue, uint oldValue, uint blockNumber, bytes32 ParentBlockhash);
}

The sender of the private transaction is randomly created for every transaction.

Correct state: BlockNumber : 0x7b7017 _value: 0x112218235e554abc10b071f703aa932e9b389bd2130c27703f6199ea0eaf68d3
Sydney 0. : BlockNumber : 0x7b7017 _value: 0x606fe089057cbb05396309f213ab96941c6a83af95acc1decbe660d2ad3868d

The failed transaction:
[ec2-user@ip-10-2-2-111 besu]$ curl -X POST --data '{"jsonrpc":"2.0","method":"priv_getPrivateTransaction","params":["0x74c37eb6c8d172ca6a41420ffbb963f848ae92eb6aaa28e85bfcaffcb4b429d5"], "id":1}' http://127.0.0.1:8545
{
"jsonrpc" : "2.0",
"id" : 1,
"result" : {
"from" : "0x22196b5f04598f720dcba13441be05269c9135d0",
"gas" : "0x1875b",
"gasPrice" : "0x4a817c800",
"hash" : "0xf5a396a5ea088d6ff1515e837c6407fd31a790039be52fe1e1af370d7c9da397",
"input" : "0x9867ef7b1724e62bce02810c4326416822902a47dafe33e8ea56eb6dd3dfffe7247cee5e",
"nonce" : "0x0",
"to" : "0xa00aa0313caf05c2876cd05765c63ad1806b23fb",
"value" : "0x0",
"v" : "0x2a",
"r" : "0xee3415e9f7f17f4c214d10ae8a2559c683acf57f3ecee2188efd9d7b06481e09",
"s" : "0xffb3634507d02a91b8831f6a84867cda7561d7a9a05f24935f902935a54cbc7",
"privateFrom" : "8+0vxIheTou+qqhpAHXqWRqfryfl4cpU+piYatksf0w=",
"privacyGroupId" : "W6d4xi8ju2N8NCSXgmaMuqTNU9dtDRfOjZrN7NbN3Z8=",
"restriction" : "restricted"
}

Xoring the Sydney0 _value with 1724e62bce02810c4326416822902a47dafe33e8ea56eb6dd3dfffe7247cee5e results in the correct value.

curl -X POST --data '{"jsonrpc":"2.0","method":"priv_getTransactionCount","params":["0x22196b5f04598f720dcba13441be05269c9135d0", "W6d4xi8ju2N8NCSXgmaMuqTNU9dtDRfOjZrN7NbN3Z8="], "id":1}' http://127.0.0.1:8545
{
"jsonrpc" : "2.0",
"id" : 1,
"result" : "0x0"
}

[MadelineMurray]

Couldn't recreate in a controlled manner. Will confirm fixed by running on Ropsten again and comparing the logs.