hedera-sdk-java icon indicating copy to clipboard operation
hedera-sdk-java copied to clipboard

Duplicate transaction reported by execute() when transaction was actually successful.

Open statop opened this issue 3 years ago • 2 comments

Description

When running the transaction tool to submit large numbers of transactions we have discovered that it is possible for the sdk to report a DUPLICATE_TRANSACTION even though the transaction went through.

Steps to reproduce

It is hard to reproduce.

If you try to submit hundreds of transactions very quickly, as txn tool does, you will likely hit this issue.

You can see it pretty regularly in failed transaction tool tests - https://github.com/hashgraph/hedera-transaction-tool-demo/runs/7826801854?check_suite_focus=true#step:8:50767

Additional context

Here is a transaction tool log file with DUPLICATE_TRANSACTION messages in it - test.debug.log

And if you look up some of the transactions that it reports as dupes you see them as successful - https://hashscan.io/#/testnet/transaction/0.0.1865-1660314600-000700000?t=1660314606.004676003

It seems likely that the sdk is thinking the transaction timed out for whatever reason, when it actually got through, then retries and gets the duplicate.

Hedera network

mainnet, testnet, previewnet, other

Version

2.16.0

Operating system

macOS

statop avatar Aug 15 '22 14:08 statop

  • [ ] Fix maxBackoff

SimiHunjan avatar Aug 15 '22 16:08 SimiHunjan

this probably helps

2022-08-15 14:05:05.914 [  731] [pool-3-thread-40] INFO  com.hedera.hashgraph.client.core.helpers.TransactionCallableWorker.process(TransactionCallableWorker.java:88) - Submitting transaction [email protected] to sdk
2022-08-15 14:05:05.931 [  731] [pool-3-thread-40] TRACE com.hedera.hashgraph.sdk.Executable.getNodeForExecute(Executable.java:411) - Using node 0.0.3 for request #1: # com.hedera.hashgraph.sdk.proto.TransactionBody
2022-08-15 14:05:07.444 [  731] [pool-3-thread-40] TRACE com.hedera.hashgraph.sdk.Executable$GrpcRequest.verboseLog(Executable.java:688) - Node IP 138.91.142.219 Timestamp 1660590307444 Transaction Type GrpcRequest
2022-08-15 14:05:07.541 [  731] [pool-3-thread-40] TRACE com.hedera.hashgraph.sdk.Executable.lambda$new$1(Executable.java:91) - Sent protobuf 2aa8010a3e0a110a0a08dcb1ea970610f0e617120318c90e120218031880cab5ee01220308b401721a0a180a0a0a03188f08108084af5f0a0a0a0318c90e10ff83af5f12660a640a2005b1a211a49bb1b5bbdbd5f79bc0bf4edf4133cfb4b6023cde0ca57a79e53cdb1a40a7de30e37dae29d50b26e9c312aa6fe6a3c34c6ca6020bdbfa8bd119d38da82cf47c7217c3ffd7cf7c281859b5e333e8138d0ea34dd2035a544bc2b3cf1fbe01
2022-08-15 14:05:08.514 [  731] [pool-3-thread-40] WARN  com.hedera.hashgraph.sdk.Executable$GrpcRequest.shouldRetryExceptionally(Executable.java:628) - Retrying node 0.0.3 in 63999 ms after failure during attempt #1: UNAVAILABLE: RST_STREAM closed stream. HTTP/2 error code: REFUSED_STREAM
2022-08-15 14:05:08.520 [  731] [pool-3-thread-40] TRACE com.hedera.hashgraph.sdk.Executable$GrpcRequest.verboseLog(Executable.java:688) - Node IP 138.91.142.219 Timestamp 1660590308520 Transaction Type GrpcRequest
2022-08-15 14:05:08.522 [  731] [pool-3-thread-40] TRACE com.hedera.hashgraph.sdk.Executable.getNodeForExecute(Executable.java:411) - Using node 0.0.3 for request #2: # com.hedera.hashgraph.sdk.proto.TransactionBody
2022-08-15 14:07:16.521 [  731] [pool-3-thread-40] TRACE com.hedera.hashgraph.sdk.Executable$GrpcRequest.verboseLog(Executable.java:688) - Node IP 138.91.142.219 Timestamp 1660590436521 Transaction Type GrpcRequest
2022-08-15 14:07:16.524 [  731] [pool-3-thread-40] TRACE com.hedera.hashgraph.sdk.Executable.lambda$new$1(Executable.java:91) - Sent protobuf 2aa8010a3e0a110a0a08dcb1ea970610f0e617120318c90e120218031880cab5ee01220308b401721a0a180a0a0a03188f08108084af5f0a0a0a0318c90e10ff83af5f12660a640a2005b1a211a49bb1b5bbdbd5f79bc0bf4edf4133cfb4b6023cde0ca57a79e53cdb1a40a7de30e37dae29d50b26e9c312aa6fe6a3c34c6ca6020bdbfa8bd119d38da82cf47c7217c3ffd7cf7c281859b5e333e8138d0ea34dd2035a544bc2b3cf1fbe01
2022-08-15 14:07:16.731 [  731] [pool-3-thread-40] TRACE com.hedera.hashgraph.sdk.Executable.lambda$new$2(Executable.java:95) - Received protobuf 080b
2022-08-15 14:07:16.732 [  731] [pool-3-thread-40] TRACE com.hedera.hashgraph.sdk.Executable$GrpcRequest.getStatus(Executable.java:652) - Received DUPLICATE_TRANSACTION response in 0.0 s from node 0.0.3 during attempt #2: # com.hedera.hashgraph.sdk.proto.TransactionResponse@83522
2022-08-15 14:07:16.732 [  731] [pool-3-thread-40] INFO  com.hedera.hashgraph.client.core.helpers.TransactionCallableWorker.process(TransactionCallableWorker.java:107) - Worker: Transaction: [email protected], failed with error. 

looks like it's getting a RST_STREAM closed stream that was actually successful, then DUPLICATE_TRANSACTION on retry

statop avatar Aug 15 '22 19:08 statop