Transaction Receipt Status as "0x0"

[syed-shamayel]

Setup Details:
We are running GoQuorum with the high availability setup over AKS.

Quorum Version: 22.4.0
Number of Parties: 2 (say Party A and Party B)
Quorum: 3 pods for both parties
Tessera: 1 node with 2 replicas (3 pods for both parties)
Validator: 4 pods with Party A, none with Party B
Other details: IBFT consensus protocol

Scenario:
Party B is executing a private transaction, with the privacy flag as 3. The transaction also emits few events. The transaction should be visible to both parties, i.e. Party A and Party B. In privateFor attribute, the Tessera public keys of both parties are passed.

Issue:
Blocks and Transaction details are replicated to all Quorum pods. Verified using geth console method - eth.getTransactionReceipt(txnHash).
However, in one of the Party B's pod, transaction status is visible as "0x0" and logs array is empty. The issue is occurring intermittently.

1/3 pod of Party B

All other pods of Party A and Party B
Logs array is filled with the event data and transaction status is "0x1"

Open Questions:

1. What could be the possible reason for one of the Quorum transaction pod having status as "0x0" and logs array as empty?
2. Internally, at what stage Transaction receipt status is set as "0x0" or "0x1"? Can you please help me understand the sequence of blocks, transaction and logs syncing?
3. When transaction status is "0x1", does that guarantee transactions are written to that Quorum node/pod?
4. At what stage, logs details are available in the transaction receipt?

[baptiste-b-pegasys]

Hello, do you have some deployment files you can provide?
About Tessera's replicas, do they share same keys?
thank you

[syed-shamayel]

What is your block period and current (or targeted) TPS?

Block period is set as 5 sec.
We post the transaction only after we get the transaction hash of the previously posted transaction. We also wait for the transaction receipt using web3Quorum.priv.waitForTransactionReceipt method for that transaction hash.

[baptiste-b-pegasys]

My hypothesis is some concurrency effect between the validated and published block and the availability of the encrypted payload on tessera.

The validators are not connected to Tessera, right?

Yet, with a block period at 5 sec and not overloaded TPS, it might be something else. I am trying a similar environment and check the workflow.

[bipeen-kumar]

@baptiste-b-pegasys Yes, the validators are not connected to the tessera. Below is the env variable set for the validator-

 - name: PRIVATE_CONFIG
   value: ignore

Also, this issue is affecting all our environments. So, if you cannot replicate this issue with your setup locally, we would very much appreciate having a call set up to look at our environment.

[bipeen-kumar]

@baptiste-b-pegasys Were you able to replicate the issue at your end or do you need any more information from our end?

[bipeen-kumar]

@baptiste-b-pegasys I was going through the logs and could not get anything out of it. Could you point me in some direction on what or where I should be looking into the logs or Shall I share the log files with you, will it help?

[baptiste-b-pegasys]

I've reread the process, as the hash of the private payload is stored in the public transaction when all Tessera exchanges are made, there is no concurrent issue possible, and no problem for the validators to be outside of the org too.

So I think we should take a deeper look in Tessera setup and its data access, because when GoQuorum plays the block, and is running the tx, it asks Tessera for the encrypted payload, and the only explanation that the tx has no logs is that the encrypted payload is not returned by Tessera.

I have to setup external DB for tessera in order to reproduce this. Can you remind me what kind of DB you are using?

If you have the time of the Tx and the logs of Tessera used by the node that has an issue, I will take a look.

In terms of ressources, is the database a managed service? Maybe the logs of the db would be interesting too.

[baptiste-b-pegasys]

new version of tessera. https://github.com/ConsenSys/tessera/releases/tag/tessera-22.10.0

not member -> no payload -> failed tx -> tx status 0x0 -> no logs
same state -> same tx -> same payload -> same logs

so logically, if you have the payload on one or more nodes and the private tx that succeeds, you should have the same logs.
But if you miss some payloads, the state is corrupted, not sure then it will get same logs.

[smvdn]

@baptiste-b-pegasys event logs not available issue recurred in one of our environments. This time as initially one transaction node was affected. While debugging further found the below difference in Quorum Transaction Node stdout

Affected Block: 291160
Environment Details: We had 3 Quorum transaction nodes with a Tessera Load Balancer. Behind the Load Balancer 3 Tessera Pods are available connected to MySQL external Databases.
Quorum logs on affected node

DEBUG[11-14|14:30:58.005] Queued delivered header or block         peer=2e5f7cb5c5333327842de9ac65bcxxxxxxxxxxce3210bcfcc3533148231xxxxxxx number=291,160 hash=e4c959..041e7d  queued=1
DEBUG[11-14|14:30:58.005] Importing propagated block               peer=2e5f7cb5c5333327842de9ac65bcxxxxxxxxxxce3210bcfcc3533148231xxxxxxx number=291,160 hash=e4c959..041e7d
TRACE[11-14|14:30:58.005] BFT: loaded voting snapshot from cache   snap.number=291,159 snap.hash=0x0327a0d2dcd47015b7f047a12c635653a7327c2d49e4400852a4987ff7xxxxx snap.epoch=30000 snap.validators="[0x354EDc1044edf4a24DA24db467B67CF07c2xxxx 0x65bc5d53114ce3210BCFcC3533148231f4B4xxxx 0xbad5CB420d4982BdC033AD1FC59FaeE96c5xxxx 0xDE0A72DE49E9c47efCD02cfAf7C50221f9exxxx]" snap.votes=[]
TRACE[11-14|14:30:58.006] BFT: loaded voting snapshot from cache   snap.number=291,159 snap.hash=0x0327a0d2dcd47015b7f047a12c635653a7327c2d49e4400852a4987ff7xxxxx snap.epoch=30000 snap.validators="[0x354EDc1044edf4a24DA24db467B67CF07c2xxxx 0x65bc5d53114ce3210BCFcC3533148231f4B4xxxx 0xbad5CB420d4982BdC033AD1FC59FaeE96c5xxxx 0xDE0A72DE49E9c47efCD02cfAf7C50221f9exxxx]" snap.votes=[]
TRACE[11-14|14:30:58.006] Propagated block                         hash=e4c959..041e7d  recipients=1 duration="925.499µs"
TRACE[11-14|14:30:58.006] Propagated block                         id=7ca93d61dcaa86ea conn=inbound         number=291,160 hash=e4c959..041e7d  td=291,161
TRACE[11-14|14:30:58.006] header data not found in ancient or level db hash=e4c959..041e7d
DEBUG[11-14|14:30:58.007] Account Extra Data root                  hash=000000..000000
DEBUG[11-14|14:30:58.007] Account Extra Data root                  hash=bf42ca..e0deaa
DEBUG[11-14|14:30:58.011] AccountExtraData root after trie commit  root=56e81f..63b421
DEBUG[11-14|14:30:58.011] AccountExtraData root after trie commit  root=bf42ca..e0deaa
DEBUG[11-14|14:30:58.011] Persisted trie from memory database      nodes=0  size=0.00B    time="2.1µs"      gcnodes=0 gcsize=0.00B gctime=0s livenodes=1 livesize=-158834.00B
DEBUG[11-14|14:30:58.011] Persisted trie from memory database      nodes=2  size=253.00B  time="18µs"       gcnodes=0 gcsize=0.00B gctime=0s livenodes=1 livesize=0.00B
DEBUG[11-14|14:30:58.011] Inserted new block                       number=291,160 hash=e4c959..041e7d  uncles=0 txs=1 gas=0 elapsed=4.841ms     root=9bd8f1..cf0d6d
INFO [11-14|14:30:58.011] Imported new chain segment               blocks=1 txs=1 mgas=0.000 elapsed=5.388ms     mgasps=0.000 number=291,160 hash=e4c959..041e7d  dirty=0.00B
TRACE[11-14|14:30:58.011] Announced block                          hash=e4c959..041e7d  recipients=1 duration=6.328ms

Quorum logs on normal node

DEBUG[11-14|14:30:58.005] Queued delivered header or block         peer=7081e68f73d2396dcfa20acxxxxxxx44edf4a24da24db467b67xxxxxxx number=291,160 hash=e4c959..041e7d  queued=1
DEBUG[11-14|14:30:58.005] Importing propagated block               peer=7081e68f73d2396dcfa20acxxxxxxx44edf4a24da24db467b67xxxxxxx number=291,160 hash=e4c959..041e7d
TRACE[11-14|14:30:58.005] BFT: loaded voting snapshot from cache   snap.number=291,159 snap.hash=0x0327a0d2dcd47015b7f047a12c635653a7327c2d49e4400852a4987ff7xxxxx snap.epoch=30000 snap.validators="[0x354EDc1044edf4a24DA24db467B67CF07c2xxxx 0x65bc5d53114ce3210BCFcC3533148231f4B4xxxx 0xbad5CB420d4982BdC033AD1FC59FaeE96c5xxxx 0xDE0A72DE49E9c47efCD02cfAf7C50221f9exxxx]" snap.votes=[]
TRACE[11-14|14:30:58.006] BFT: loaded voting snapshot from cache   snap.number=291,159 snap.hash=0x0327a0d2dcd47015b7f047a12c635653a7327c2d49e4400852a4987ff7xxxxx snap.epoch=30000 snap.validators="[0x354EDc1044edf4a24DA24db467B67CF07c2xxxx 0x65bc5d53114ce3210BCFcC3533148231f4B4xxxx 0xbad5CB420d4982BdC033AD1FC59FaeE96c5xxxx 0xDE0A72DE49E9c47efCD02cfAf7C50221f9exxxx]" snap.votes=[]
TRACE[11-14|14:30:58.006] Propagated block                         hash=e4c959..041e7d  recipients=2 duration="843.799µs"
TRACE[11-14|14:30:58.006] Propagated block                         id=3e80d3a8c65f3af0 conn=inbound         number=291,160 hash=e4c959..041e7d  td=291,161
TRACE[11-14|14:30:58.006] Propagated block                         id=7b0b0c876e730d12 conn=staticdial      number=291,160 hash=e4c959..041e7d  td=291,161
TRACE[11-14|14:30:58.006] header data not found in ancient or level db hash=e4c959..041e7d
DEBUG[11-14|14:30:58.006] Account Extra Data root                  hash=000000..000000
DEBUG[11-14|14:30:58.006] Account Extra Data root                  hash=2eb035..6f9962
TRACE[11-14|14:30:58.026] Accepted connection                      addr=100.0.0.6:21032
TRACE[11-14|14:30:58.028] Verify hashes of affected contracts      expectedHashes="map[0x14a00c99ef673ffa4b310185efd8e0f6b02e812ea96d26d177b07359fcc3464e3deb90bc5d15c99334dfa873e9aade57164396655b8ab3cxxxxxxxfff:{} 0x50a1548e575894240fe9cf1896400d5ac06a718d5163db9d8114c97fccf1997ad3af943896955e61f70bac538cb1f52ba2f4de70a046e17c29bxxxx132:{} 0xb99d406c94fd8a487de47925960bb1bf68610fdb6d7513034d8b346adcd23d8166b938c4cd9ca9776db777bf38dcbe4b47axxxxxxx4f7:{} 0xd1f8824866d014d25ecb4bc16495c886b5184c9365d46685b06d55601ab7470900706d977b2012268e3ff923305dd303f86b899d5e641750daeebxxxxxx905:{} 0xee598133fa263f19c8f4b7dfb6e94a9d414212b98bad41b3c574895af570bba13cac37fd426d9f152559df519fb55a0f4c12f69bc6342xxxxxxxc8e:{}]" numberOfAffectedAddresses=5
TRACE[11-14|14:30:58.028] Privacy metadata                         affectedAddress=0x2839136EBa63897b25B39DAAF3606CE78xxxxxx metadata="&{CreationTxHash:0xb99d406c94fd8a487de47925960bb1bf68610fdb6d7513034d8b346adcd23d8166b938c4cd9ca9776db777bf38dcbe4b47axxxxxxx4f7 PrivacyFlag:3}"
TRACE[11-14|14:30:58.028] Privacy metadata                         affectedAddress=0x5C1FD8260dDF8dDC222668E51fa04Ec0xxxxxxx metadata="&{CreationTxHash:0xee598133fa263f19c8f4b7dfb6e94a9d414212b98bad41b3c574895af570bba13cac37fd426d9f152559df519fb55a0f4c12f69bc6342xxxxxxxc8e PrivacyFlag:3}"
TRACE[11-14|14:30:58.028] Privacy metadata                         affectedAddress=0xD83Fb8a5C94D8AdC4444e2bdcCEa796F88xxxxxx metadata="&{CreationTxHash:0x14a00c99ef673ffa4b310185efd8e0f6b02e812ea96d26d177b07359fcc3464e3deb90bc5d15c99334dfa873e9aade57164396655b8ab3cxxxxxxxfff PrivacyFlag:3}"
TRACE[11-14|14:30:58.028] Privacy metadata                         affectedAddress=0x534ecf46DEBbEE285Aa1053De30cB52fA8xxxxxx metadata="&{CreationTxHash:0xd1f8824866d014d25ecb4bc16495c886b5184c9365d46685b06d55601ab7470900706d977b2012268e3ff923305dd303f86b899d5e641750daeebxxxxxx905 PrivacyFlag:3}"
TRACE[11-14|14:30:58.028] Privacy metadata                         affectedAddress=0x3BaFE812b39a20f3C76285a16Cb8954bxxxxxx metadata="&{CreationTxHash:0x50a1548e575894240fe9cf1896400d5ac06a718d5163db9d8114c97fccf1997ad3af943896955e61f70bac538cb1f52ba2f4de70a046e17c29bxxxx132 PrivacyFlag:3}"
TRACE[11-14|14:30:58.028] Verify merkle root                       merkleRoot=79a530..9bb218
DEBUG[11-14|14:30:58.029] AccountExtraData root after trie commit  root=56e81f..63b421
DEBUG[11-14|14:30:58.029] AccountExtraData root after trie commit  root=2eb035..6f9962
DEBUG[11-14|14:30:58.029] Persisted trie from memory database      nodes=46 size=8.80KiB  time="201.4µs"    gcnodes=0 gcsize=0.00B gctime=0s livenodes=1 livesize=-182894.00B
DEBUG[11-14|14:30:58.029] Persisted trie from memory database      nodes=2  size=253.00B  time="15.8µs"     gcnodes=0 gcsize=0.00B gctime=0s livenodes=1 livesize=0.00B
DEBUG[11-14|14:30:58.030] Inserted new block                       number=291,160 hash=e4c959..041e7d  uncles=0 txs=1 gas=0 elapsed=23.276ms    root=9bd8f1..cf0d6d
INFO [11-14|14:30:58.030] Imported new chain segment               blocks=1 txs=1 mgas=0.000 elapsed=23.955ms    mgasps=0.000 number=291,160 hash=e4c959..041e7d  dirty=0.00B
TRACE[11-14|14:30:58.030] Announced block                          hash=e4c959..041e7d  recipients=0 duration=24.768ms

The privacy metadata retrieval is not happening on affected node. Also checked on the Tessera Logs, could find Request /transaction event is there only for 2 Transaction Nodes, possibly the affected Transaction Node haven't even requested for the Private Transaction details.

Will it be a block metadata received for the Block 291160 by the affected Transaction Node is corrupted?

Note: All the Transaction Nodes have the same Transaction Hash on the Block.

[baptiste-b-pegasys]

It looks like that the received block is the same: same hash, same number of transaction.

I am not sure about the AccountExtraData, which is different but might be based on the node address.

In order to have the Verify hashes of affected contracts, here are the conditions to met:

func (pmh *privateMessageHandler) mustVerify() bool {
	return pmh.hasPrivatePayload && pmh.receivedPrivacyMetadata != nil && pmh.stAPI.IsPrivacyEnhancementsEnabled()
}

1. it's a private message
2. it has received the private payload and its metadata from Tessera
3. privacy enhancement is enabled

Normally, if you don't have the the private payload when it's a private message, it's because the node is not a member.
Yet, Tessera could be in error, or the setup is not correct, that you don't get this data even so you think you are a member.

Have you got a change to test the new tessera?
Could be an idea to add logs in the area where GoQ loads the private payload and private metadata to see what happens.

[smvdn]

We had upgraded the Tessera Image to 22.10.0 now. Will test with the latest Image and update if the issue recurs.

Is there any option to add a retry for Quorum to Tessera API call failures?

[baptiste-b-pegasys]

If there is an error from Tessera, we could add some retry loop backoff and add more logs.

[antonydenyer]

fixed with #1574