SDK Sends Repetitive Requests (no replays allowed)

[cheeseandcereal]

• SDK Version: 4.0.0
• Node Version: 10.16.0
• Platform: Linux

For some reason, the javascript SDK occasionally sends repeat requests which trigger the replay protection on Dragonchain (Previous matching request found (no replays allowed)). This is a bug that only occurs with this SDK.

Cause at this time is still unknown. If any details are discovered, this ticket should be updated.

[WhiteRavenTechnology]

• SDK Version: 3.2.0
• Node Version: 10.16.3
• Platform: Windows & Linux

Have experienced with queryBlocks calls similar to
client.queryBlocks({ luceneQuery: 'block_id:>${start_block_id} AND timestamp:>=${start_timestamp}', limit: 50, sort: 'block_id:asc'})

• Calls run in a loop until there are no blocks remaining to pull
• The next request in the loop does not occur until the previous request is complete
• Each request is made on a "fresh" client instance (local webpage makes ajax call -> intermediary nodejs express server -> invokes createClient({credentials}) then client.queryBlocks())
• The EXACT query should never be repeated (intentionally) with my code
• Adding up to 500ms forced delay between calls has no effect on the frequency of this error

Interestingly, I've ONLY experienced it when querying a specific managed L2 node (public ID: cj4i7y1ucMtuz1jqTfa6edZ8x1XH85DU3gL8KaJZ1e2c). Once it errors, if I try to run the exact query (starting from the same block number) it continues to fail. If I bump the block ID by one, it "clears the pipes" and I can resume where I left off (with the original query) until a few more pulls later it errors again.

Other managed L3s (21mPVWRyyJHNTTQZEgy1hqefUpzsgCLLt9fhkRWQQrTTt) and unmanaged L2s (21aVsbEYCfSpe3aBaoT3J4Kp1Q8mjF7A6BSZF8yBGRJTD work fine.

In fact, on the managed L3, I'm able to rapid-fire requests to pull all 15000+ blocks 50 at a time and have done so perhaps 15-20 times in testing with no error at any time. The managed L2, though, errors within the first 5 calls or so every time.

The application experiencing this issue can be found here:
https://github.com/Dragonchain-Community/dragonchain-uvn-block-explorer/tree/dev

[deanshelton913]

The problem area is this line in think https://github.com/dragonchain/dragonchain-sdk-javascript/blob/master/src/services/dragonchain-client/DragonchainClient.ts#L1324

I suggest that we use more precise NODEJS timing functions.
Suggest this --> https://nodejs.org/api/process.html#process_process_hrtime_bigint

process.hrtime.bigint()

[cheeseandcereal]

The date has to be sent as an ISO 8601 time string, so I don't know if getting a bigint unix timestamp would help. Additionally that function you linked isn't compatible with node 8, which we support, so we can't use that function anyways.

I'm also not 100% convinced it's that line with the issue, because I've seen this error happen when performing a query manually in the node repl for the first time and I still get the error. Could maybe be the http request library doing some weird re-request?

Either way, this warrants more investigation.

[deanshelton913]

for(let i=0;i<100;i++){console.log(new Date().now().toISOString())}

yields:

2019-09-16T17:36:26.226Z
2019-09-16T17:36:26.226Z
2019-09-16T17:36:26.226Z
2019-09-16T17:36:26.226Z
2019-09-16T17:36:26.226Z
2019-09-16T17:36:26.226Z
2019-09-16T17:36:26.227Z
2019-09-16T17:36:26.227Z
2019-09-16T17:36:26.227Z
2019-09-16T17:36:26.227Z
2019-09-16T17:36:26.227Z
2019-09-16T17:36:26.227Z
2019-09-16T17:36:26.227Z
2019-09-16T17:36:26.227Z
2019-09-16T17:36:26.227Z
2019-09-16T17:36:26.227Z
2019-09-16T17:36:26.227Z
2019-09-16T17:36:26.227Z
2019-09-16T17:36:26.227Z
2019-09-16T17:36:26.227Z
2019-09-16T17:36:26.227Z```

[deanshelton913]

if we had more precision in that string we could solve this, but i actually agree that bigint might not be exactly what we need... after reading further on it

[cheeseandcereal]

Yeah, of course you can get a raw for loop to generate the same date string when there's no other logic. But I've also seen this error occur when performing a single request, so although getting the date iso string may be a problem, I'm still not convinced that's the root cause.

[WhiteRavenTechnology]

#begindumbness
In my case, I'm running into the issue when rapid-firing queryBlocks requests: doesn't the replay protection also depend on the actual query (and not just the timing of requests; so two different requests, even at the same instant, should theoretically go through fine)? In that case, I'd think we're back to some kind of poor error condition handling with the http request library.

I shouldn't ever be intentionally sending the same request through twice at all, and it continues to error if I DO reissue the same request, even seconds or minutes apart, until I issue a new (different) request.
#enddumbness

[cheeseandcereal]

Yeah, the replay protection only comes into play if the signature of the request is identical, which means all parts of the request, including query parameters and time stamp would have to be identical to trigger replay protection.

[WhiteRavenTechnology]

Okay, pure speculation here: is it possible that the SDK client is reusing previous fetch options somehow if the query parameters match a previous failed request? If timestamp is enough to get past the replay protection, I'd think reissuing the same failed request a few seconds or more later would DEFINITELY get it through, but it doesn't.

[cheeseandcereal]

I'm not sure why that would happen, but I wouldn't immediately rule it out until I see proof otherwise. There's no code to 'cache' any sort of request data or anything, but yeah, if you're making a request seconds later, it absolutely should work fine.

[WhiteRavenTechnology]

Let me see if I can force-break it again and prove that idea.

[WhiteRavenTechnology]

Disregard that thought. It was a red herring. Once I get it to error, I can rerun that request over and over (with a few seconds between each request), and whether it succeeds appears to be random (no specific trigger from my end).

I'll leave this to the experts. 😄

It IS still ONLY happening on that specific managed L2 for me though. Not a single issue with other nodes.

[deanshelton913]

I am fairly confident that the timestamp precision is the issue. Python gives 6 digits for the miliseconds. Node gives 3.
Even in a for-loop within python, 6 is sufficient

# Python
for x in range(0, 100): print(datetime.datetime.utcnow().isoformat() + 'Z')

2019-09-16T18:28:09.086199Z
2019-09-16T18:28:09.086205Z
2019-09-16T18:28:09.086211Z
2019-09-16T18:28:09.086216Z
2019-09-16T18:28:09.086221Z
2019-09-16T18:28:09.086226Z
2019-09-16T18:28:09.086232Z
2019-09-16T18:28:09.086237Z
2019-09-16T18:28:09.086242Z
2019-09-16T18:28:09.086248Z
2019-09-16T18:28:09.086253Z
2019-09-16T18:28:09.086259Z
2019-09-16T18:28:09.086264Z
2019-09-16T18:28:09.086269Z
2019-09-16T18:28:09.086275Z
2019-09-16T18:28:09.086280Z