Private Transactions "not found" after incoming external private marker transaction caused errors in Besu Node

[eum602]

environment

• I have 2 pair of nodes (orion-besu) configured to send private transactions
• Node A: Besu Node A, Orion Node A
• Node B: Besu Node B, Orion Node B

VMs: On Google Cloud

• Node A:
• Besu Node A: 2vcpu, 8GB RAM
• Orion Node A: 2vcpu, 8GB RAM
• Node B:
• Besu Node B: 2vcpu, 8GB RAM
• Orion Node B: 2vcpu, 8GB RAM

Scenario:

• I shutdown Node A, I mean, Besu Node A, Orion Node A
• I shutdown Orion Node B
• I didn't disable the orion flags on Besu node B
• after some days an incoming private marker transaction (TX "n") arrived via p2p to Besu Node B
• Naturally an error appeared in the "ERROR" level logs, stating the Orion Node B is not reachable:
  2021-09-23T15:59:05.658+0000 ERROR Can not communicate with enclave is it up? org.hyperledger.besu.enclave.EnclaveIOException: Enclave Communication Failed at org.hyperledger.besu.enclave.VertxRequestTransmitter.sendRequest(VertxRequestTransmitter.java:88) ~[enclave-20.10.2.jar:?] at org.hyperledger.besu.enclave.VertxRequestTransmitter.post(VertxRequestTransmitter.java:42) ~[enclave-20.10.2.jar:?] at org.hyperledger.besu.enclave.Enclave.post(Enclave.java:150) ~[enclave-20.10.2.jar:?] at org.hyperledger.besu.enclave.Enclave.receive(Enclave.java:81) ~[enclave-20.10.2.jar:?] at org.hyperledger.besu.ethereum.mainnet.precompiles.privacy.PrivacyPrecompiledContract.getReceiveResponse(PrivacyPrecompiledContract.java:235) ~[besu-core-20.10 .2.jar:20.10.2] at org.hyperledger.besu.ethereum.mainnet.precompiles.privacy.PrivacyPrecompiledContract.compute(PrivacyPrecompiledContract.java:115) ~[besu-core-20.10.2.jar:20.1 0.2] at org.hyperledger.besu.ethereum.mainnet.MainnetMessageCallProcessor.executePrecompile(MainnetMessageCallProcessor.java:133) ~[besu-core-20.10.2.jar:20.10.2] at org.hyperledger.besu.ethereum.mainnet.MainnetMessageCallProcessor.start(MainnetMessageCallProcessor.java:61) ~[besu-core-20.10.2.jar:20.10.2] at org.hyperledger.besu.ethereum.mainnet.AbstractMessageProcessor.process(AbstractMessageProcessor.java:163) ~[besu-core-20.10.2.jar:20.10.2] at org.hyperledger.besu.ethereum.mainnet.MainnetTransactionProcessor.process(MainnetTransactionProcessor.java:440) ~[besu-core-20.10.2.jar:20.10.2] at org.hyperledger.besu.ethereum.mainnet.MainnetTransactionProcessor.processTransaction(MainnetTransactionProcessor.java:354) ~[besu-core-20.10.2.jar:20.10.2] at org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:147) ~[besu-core-20.10.2.jar:20.10.2] at org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:40) ~[besu-core-20.10.2.jar:20.10.2] at org.hyperledger.besu.ethereum.mainnet.PrivacyBlockProcessor.processBlock(PrivacyBlockProcessor.java:96) ~[besu-core-20.10.2.jar:20.10.2] at org.hyperledger.besu.ethereum.mainnet.BlockProcessor.processBlock(BlockProcessor.java:61) ~[besu-core-20.10.2.jar:20.10.2] at org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:96) ~[besu-core-20.10.2.jar:20.10.2] at org.hyperledger.besu.ethereum.mainnet.MainnetBlockImporter.importBlock(MainnetBlockImporter.java:45) ~[besu-core-20.10.2.jar:20.10.2] at org.hyperledger.besu.ethereum.core.BlockImporter.importBlock(BlockImporter.java:44) ~[besu-core-20.10.2.jar:20.10.2] at org.hyperledger.besu.ethereum.eth.sync.fullsync.FullImportBlockStep.accept(FullImportBlockStep.java:59) ~[besu-eth-20.10.2.jar:20.10.2] at org.hyperledger.besu.ethereum.eth.sync.fullsync.FullImportBlockStep.accept(FullImportBlockStep.java:31) ~[besu-eth-20.10.2.jar:20.10.2] at org.hyperledger.besu.services.pipeline.CompleterStage.run(CompleterStage.java:37) ~[besu-pipeline-20.10.2.jar:20.10.2] at org.hyperledger.besu.services.pipeline.Pipeline.lambda$runWithErrorHandling$3(Pipeline.java:130) ~[besu-pipeline-20.10.2.jar:20.10.2] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?] at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?] at java.lang.Thread.run(Thread.java:834) [?:?] Caused by: java.util.concurrent.ExecutionException: io.netty.channel.ConnectTimeoutException: connection timed out: /10.128.0.12:4444
• In the "INFO" level log of that node a critical error appeared:
  2021-09-23T15:59:08.304+0000 INFO Saving announced block 30347286 (0x1b5ebbbce65885bb013d87e0ec4d064cf3f2db9c13a934efc6d7654a38d9bfde) for future import 2021-09-23T15:59:10.138+0000 INFO Saving announced block 30347287 (0x1f4aa10b620bec7a6e47049acfad18637382b1e4797f33683ab232aac2549d83) for future import 2021-09-23T15:59:12.186+0000 INFO Saving announced block 30347288 (0xf4b460d182945b46c632ee50e9b9f7f091560bdd30c01677b24dba61b173b216) for future import 2021-09-23T15:59:14.036+0000 INFO Block processing error: transaction invalid 'INTERNAL_ERROR'. Block 0xbf2141be6b8441cd01e11dcd89835c9aa0829d8a2de4555052bcf9faab93d1a5 Transaction 0x86f5cd379b4927da5ac3b6de4107d03270cf9dba4fbcf6c13f8208d18bc5e0f9 2021-09-23T15:59:14.145+0000 INFO Saving announced block 30347289 (0x5ba574adbc7304a4a83ae6ea698f3e7fa0f176b8bb7cb372409245a10ce04bf5) for future import 2021-09-23T16:28:06.344+0000 INFO No sync target, waiting for peers: 0 2021-09-23T16:28:11.345+0000 INFO No sync target, waiting for peers: 0 2021-09-23T16:28:11.545+0000 INFO No sync target, waiting for peers: 1 2021-09-23T16:47:16.687+0000 INFO No sync target, waiting for peers: 0 2021-09-23T16:47:21.688+0000 INFO No sync target, waiting for peers: 0 2021-09-23T16:47:26.689+0000 INFO No sync target, waiting for peers: 0 2021-09-23T16:47:28.742+0000 INFO No sync target, waiting for peers: 1 2021-09-23T16:54:58.785+0000 INFO No sync target, waiting for peers: 0 2021-09-23T16:54:59.642+0000 INFO No sync target, waiting for peers: 1 2021-09-23T17:21:09.797+0000 INFO No sync target, waiting for peers: 0 2021-09-23T17:21:14.799+0000 INFO No sync target, waiting for peers: 0
• After that Besu Node B stopped synchronizing even when it has other peer connections
• They way I found to make it start synchronizing again was disabling the orion flags and restarting the Besu Node B again.
• After the Besu Node B finished the synchronization process I activated again the orion flag in the Besu Node B as well as turning on the Orion Node B.
• I started Besu Node A (the orion flags were activated but the Orion Node A wasn't)
• During the synchronization the Besu Node A reached the imported block where the TX "n" was included. Because of the fact that the node had orion flags activated but not able to communicate to Orion Node A, since it was not running; the Besu Node A showed the following critical message:
  2021-09-24T04:44:12.601+0000 INFO Import reached block 30346400 (0x7003..3297), 0.868 Mg/s, Peers: 6 2021-09-24T04:44:40.652+0000 INFO Import reached block 30346600 (0xaf67..a314), 0.904 Mg/s, Peers: 6 2021-09-24T04:45:12.061+0000 INFO Import reached block 30346800 (0xbf90..88c7), 0.953 Mg/s, Peers: 6 2021-09-24T04:45:43.858+0000 INFO Import reached block 30347000 (0x7690..704b), 0.950 Mg/s, Peers: 6 2021-09-24T04:46:16.077+0000 INFO Import reached block 30347200 (0xe63f..ffae), 0.991 Mg/s, Peers: 6 2021-09-24T04:46:34.631+0000 INFO Block processing error: transaction invalid 'INTERNAL_ERROR'. Block 0xbf2141be6b8441cd01e11dcd89835c9aa0829d8a2de4555052bcf9faab93d1a5 Transaction 0x86f5cd379b4927da5ac3b6de4107d03270cf9dba4fbcf6c13f8208d18bc5e0f9 2021-09-24T04:46:37.039+0000 INFO Found common ancestor with peer 0xfe50d1c3d1ebbc37cd... at block 30347272 2021-09-24T04:46:38.432+0000 INFO Block processing error: transaction invalid 'INTERNAL_ERROR'. Block 0xbf2141be6b8441cd01e11dcd89835c9aa0829d8a2de4555052bcf9faab93d1a5 Transaction 0x86f5cd379b4927da5ac3b6de4107d03270cf9dba4fbcf6c13f8208d18bc5e0f9 2021-09-24T04:46:40.603+0000 INFO Found common ancestor with peer 0xb97f1b94e3a5e78de9... at block 30347272 2021-09-24T04:46:41.963+0000 INFO Block processing error: transaction invalid 'INTERNAL_ERROR'. Block 0xbf2141be6b8441cd01e11dcd89835c9aa0829d8a2de4555052bcf9faab93d1a5 Transaction 0x86f5cd379b4927da5ac3b6de4107d03270cf9dba4fbcf6c13f8208d18bc5e0f9 2021-09-24T04:46:44.121+0000 INFO Found common ancestor with peer 0x140626be59e4f2c57a... at block 30347272 2021-09-24T04:46:45.366+0000 INFO Block processing error: transaction invalid 'INTERNAL_ERROR'. Block 0xbf2141be6b8441cd01e11dcd89835c9aa0829d8a2de4555052bcf9faab93d1a5 Transaction 0x86f5cd379b4927da5ac3b6de4107d03270cf9dba4fbcf6c13f8208d18bc5e0f9 2021-09-24T04:47:22.383+0000 INFO No sync target, waiting for peers: 1 2021-09-24T04:47:24.585+0000 INFO No sync target, waiting for peers: 2 2021-09-24T05:00:44.650+0000 INFO No sync target, waiting for peers: 1 2021-09-24T05:00:49.651+0000 INFO No sync target, waiting for peers: 1 2021-09-24T05:00:54.652+0000 INFO No sync target, waiting for peers: 1 2021-09-24T05:00:55.859+0000 INFO No sync target, waiting for peers: 2 2021-09-24T05:10:15.905+0000 INFO No sync target, waiting for peers: 1 2021-09-24T05:10:20.905+0000 INFO No sync target, waiting for peers: 1
• They way I found to make it start synchronizing again was disabling the orion flags and restarting the Besu Node A again.
• After the Besu Node A finished the synchronization process I activated again the orion flag in the Besu Node A as well as turning on the Orion Node A.
• All seemed good, but after trying to send some private transaction between Nodes A and B the node returned the following message, like if the node wasn't able to find some private state which was already created before all this issue happened.
  Caused by: org.web3j.tx.exceptions.ContractCallException: Empty value (0x) returned from contract at org.web3j.tx.Contract.executeCallSingleValueReturn(Contract.java:313) at org.web3j.tx.Contract.lambda$executeRemoteCallSingleValueReturn$1(Contract.java:397) at org.web3j.protocol.core.RemoteCall.send(RemoteCall.java:42) at com.everis.blockchain.cadena.Cadena.getVisibility(Cadena.java:135) at com.cadena.provider.config.blockchain.ApplicationBlockChain.setVissibleRMA(ApplicationBlockChain.java:156) at com.cadena.provider.config.blockchain.ApplicationBlockChain.instanceICadena(ApplicationBlockChain.java:144) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.springframework.beans.factory.support.SimpleInstantiationStrategy.instantiate(SimpleInstantiationStrategy.java:154) ... 28 common frames omitted
  note: I noticed that I was still able to create new privacyGroups and even deploy new private smart contracts on the newly created privacy group, but totally unable to recover past states.

[ccamaleon5]

It is recommended not to modify the communication configuration between Besu and Orion that comes by default when deploying the services. This is because Orion node was disconnected and the communication between Besu and Orion could not be established because the privacy flags were disabled in Besu.

The synchronization of the Besu blocks did not occur because the private transaction was waiting to find the Orion service, which, as the processing time of the private transaction exceeded, no more blocks could be synchronized.

The recommendation is to migrate to Tessera, since the Orion service is deprecated.

We have deployment scripts for Tessera in https://github.com/lacchain/besu-pro-testnet/blob/master/DEPLOY_NODE.md#besu--oriontessera-installation