client: Set conf deadline per asset. #1552

JoeGruffins · 2022-03-30T09:19:28Z

Ethereum appears to need a little more time to find swap confirmations
sometimes on testnet. Make the confirmation deadline a per-asset
constant and double it for eth.

closes #1537

JoeGruffins · 2022-03-31T02:59:16Z

If pending you can see here where the error from PendingCallContract is ignored, but it is probably failing from the same context.DeadlineExceeded
https://github.com/ethereum/go-ethereum/blob/127dc5982e3484406eae0631326bbc356f914749/accounts/abi/bind/base.go#L173-L181

So, not doing pending gives us a better error.

I think we are getting this five second timeout for the contract call https://github.com/ethereum/go-ethereum/blob/127dc5982e3484406eae0631326bbc356f914749/rpc/client.go#L44

I don't guess we don't need to worry about pending state... For one it doesn't seem to work right, and for the other block times are fast enough I think we can wait for our txn to be mined.

chappjc · 2022-04-04T16:54:46Z

I think we are getting this five second timeout for the contract call

Looks to me like it's being passed from us to the contract via bind.CallOpts, which would ultimately come from confCheckTimeout at

dcrdex/client/core/trade.go

Line 29 in c77da58

const confCheckTimeout = 2 * time.Second

Should we make that longer?

I don't guess we don't need to worry about pending state... For one it doesn't seem to work right, and for the other block times are fast enough I think we can wait for our txn to be mined.

Also, pending with a LES (light) client is kinda flakey and unpredictable all around. Under what circumstances would pending contract state even be possible to determine?

If we do not do pending, as in this PR, why does a deadline exceeded "always happen once for new swaps"? I would think the CallContract would return as fast as usual and we'd get dexeth.SSNone pretty much right away.

If pending you can see here where the error from PendingCallContract is ignored, but it is probably failing from the same context.DeadlineExceeded
https://github.com/ethereum/go-ethereum/blob/127dc5982e3484406eae0631326bbc356f914749/accounts/abi/bind/base.go#L173-L181

Does that seem like a go-ethereum bug?

JoeGruffins · 2022-04-05T01:16:26Z

confCheckTimeout

oh! How'd I miss that... Will try increasing.

Declared in trade.go and used in wallet.go, ok.

JoeGruffins · 2022-04-05T08:15:01Z

Setting confCheckTimeout to ten seconds has stopped the timeouts completely for me where I was seeing them. So... Could we make it a per wallet thing? I think we want to up eth some, but I don't guess we need to for other coins.

Under what circumstances would pending contract state even be possible to determine?

I don't know without digging through the code... but it's probably safe to assume the light client is not capable of calculating the evm state by itself.

why does a deadline exceeded "always happen once for new swaps"?

Again not sure, I guess it just takes a while to find them at first as I am seeing no errors after increasing the timeout x5. Will change the comment. I can set up some timers to see how long it usually takes on testnet.

Does that seem like a go-ethereum bug?

Bad practice leading to possible bug? It would be better if they returned the context deadline error there. It would have helped with our debugging. Guess I could make an issue...

JoeGruffins · 2022-04-05T08:27:56Z

ethereum/go-ethereum#24645

JoeGruffins · 2022-04-07T07:14:37Z

Throwing in some logs:

2022-04-07 06:40:31.361 [TRC] CORE: Checking confirmations on our OWN swap txn 0x753914cd1484a15eed693a5b8504979589964d5da182295cbe7ede9d20ede8d0 (eth)...
2022-04-07 06:40:31.398 [DBG] CORE: Received valid ack for 'init' request for match 67a0ad4ad94ec14afe8d44aeb7bae56cbbda689ee4b33456d539dc48c2d5ba1f
2022-04-07 06:40:31.399 [DBG] CORE: Received valid ack for 'init' request for match 4e25a5ad17b47c907ba8053061509cc2e43d130dc56302fd5da630b951465a9c
*************************************************
swap confs took 1.087273724s
2022-04-07 06:40:32.448 [TRC] CORE: notify: |DATA| (match)
2022-04-07 06:40:32.449 [TRC] CORE: Checking confirmations on our OWN swap txn 0x7ec8ac892bea7af4683f6bf78dbabf1d5d2cbb87772112ca6568f36832dc0648 (eth)...
*************************************************
swap confs took 562.181317ms
2022-04-07 06:40:33.012 [TRC] CORE: notify: |DATA| (match)
2022-04-07 06:40:33.013 [TRC] CORE: Checking confirmations on our OWN swap txn 0xdd029808b4f5552c157fada4f0bda19033bd7d9eb262f1d015adab4262fc35c2 (eth)...
*************************************************
swap confs took 375.494µs
2022-04-07 06:40:33.013 [TRC] CORE: notify: |DATA| (match)
2022-04-07 06:40:33.014 [TRC] CORE: Checking confirmations on our OWN swap txn 0x5205414186dd8322e1414816d3c3484fd132d5bfd4e055ca7788f9abda99c199 (eth)...
*************************************************
swap confs took 494.166µs
2022-04-07 06:40:33.014 [TRC] CORE: notify: |DATA| (match)
2022-04-07 06:40:33.015 [TRC] CORE: Checking confirmations on COUNTERPARTY swap txn 0x5ed41a2a2f5799c4a318cf59256f71add8c916072739891267e5ec09363b8523 (eth)...
*************************************************
swap confs took 457.648µs

And the highest spike I've seen is:

swap confs took 2.406904949s

But it doesn't look like it has to do anything with it being the first fetch. Just seems to go up and down randomly right now, due to network conditions I guess.

I have not seen 3+ though, so maybe setting to three seconds for eth is safe. Not sure if mainnet would be different.

The client logs, eth and dcr are mixed... but the longer ones are eth
out2.txt

JoeGruffins · 2022-04-07T07:15:29Z

I think it's probably better to error now that we have more information. If it errors too much for mainnet, we would need to up the deadline more I guess.

Ethereum appears to need a little more time to find swap confirmations sometimes on testnet. Make the confirmation deadline a per-asset constant and double it for eth.

JoeGruffins · 2022-04-07T08:05:56Z

Apologies, the pr changed a lot.

chappjc · 2022-04-08T03:35:03Z

Apologies, the pr changed a lot.

No problem. Thanks for characterizing execution time. 4 sec does seem good for ETH given what you've shown.

chappjc · 2022-04-08T03:37:21Z

client/asset/dcr/dcr.go

+	ctx, cancel := context.WithTimeout(ctx, confCheckTimeout)
+	defer cancel()


Now I'm reconsidering timeouts for the dcr and spv wallets if they need to do a cfilters scan because those can be more time consuming.

Actually, did you mean to skip BTC's timeout in this PR?

It looked like btc didn't use the context. Does it?

dcrdex/client/asset/btc/btc.go

Lines 2766 to 2769 in 11fe415

// SwapConfirmations gets the number of confirmations for the specified swap

// by first checking for a unspent output, and if not found, searching indexed

// wallet transactions.

func (btc *baseWallet) SwapConfirmations(_ context.Context, id dex.Bytes, contract dex.Bytes, startTime time.Time) (uint32, bool, error) {

Ah, good point. We have a TODO to update call so a context gets used, but you're right it's not used now.

chappjc

Seems good. Let's see how this goes.

chappjc · 2022-04-15T14:31:58Z

BTW, nice work with ethereum/go-ethereum#24645. I'll update #1542 to consume that commit at least

JoeGruffins force-pushed the ignoredeadlineexceeded branch from aeacb90 to 8f9fe9d Compare March 31, 2022 03:02

JoeGruffins marked this pull request as ready for review March 31, 2022 03:18

JoeGruffins mentioned this pull request Apr 5, 2022

trading: timed out waiting for "init" response #1561

Closed

JoeGruffins force-pushed the ignoredeadlineexceeded branch from 8f9fe9d to 2ca36ba Compare April 7, 2022 07:55

client: Set conf deadline per asset.

8cb2bf6

Ethereum appears to need a little more time to find swap confirmations sometimes on testnet. Make the confirmation deadline a per-asset constant and double it for eth.

JoeGruffins force-pushed the ignoredeadlineexceeded branch from 2ca36ba to 8cb2bf6 Compare April 7, 2022 08:03

JoeGruffins changed the title ~~client/eth: Ignore deadline exceeded.~~ client: Set conf deadline per asset. Apr 7, 2022

chappjc reviewed Apr 8, 2022

View reviewed changes

chappjc approved these changes Apr 15, 2022

View reviewed changes

chappjc merged commit 85dcae7 into decred:master Apr 15, 2022

chappjc added this to the 0.5 milestone Apr 21, 2022

chappjc added the ETH label Aug 26, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

client: Set conf deadline per asset. #1552

client: Set conf deadline per asset. #1552

JoeGruffins commented Mar 30, 2022 •

edited

JoeGruffins commented Mar 31, 2022 •

edited

chappjc commented Apr 4, 2022

JoeGruffins commented Apr 5, 2022 •

edited

JoeGruffins commented Apr 5, 2022

JoeGruffins commented Apr 5, 2022

JoeGruffins commented Apr 7, 2022

JoeGruffins commented Apr 7, 2022

JoeGruffins commented Apr 7, 2022

chappjc commented Apr 8, 2022

chappjc Apr 8, 2022

JoeGruffins Apr 8, 2022

JoeGruffins Apr 8, 2022

chappjc Apr 8, 2022

chappjc left a comment

chappjc commented Apr 15, 2022

		ctx, cancel := context.WithTimeout(ctx, confCheckTimeout)
		defer cancel()

	// SwapConfirmations gets the number of confirmations for the specified swap
	// by first checking for a unspent output, and if not found, searching indexed
	// wallet transactions.
	func (btc *baseWallet) SwapConfirmations(_ context.Context, id dex.Bytes, contract dex.Bytes, startTime time.Time) (uint32, bool, error) {

client: Set conf deadline per asset. #1552

client: Set conf deadline per asset. #1552

Conversation

JoeGruffins commented Mar 30, 2022 • edited

JoeGruffins commented Mar 31, 2022 • edited

chappjc commented Apr 4, 2022

JoeGruffins commented Apr 5, 2022 • edited

JoeGruffins commented Apr 5, 2022

JoeGruffins commented Apr 5, 2022

JoeGruffins commented Apr 7, 2022

JoeGruffins commented Apr 7, 2022

JoeGruffins commented Apr 7, 2022

chappjc commented Apr 8, 2022

chappjc Apr 8, 2022

Choose a reason for hiding this comment

JoeGruffins Apr 8, 2022

Choose a reason for hiding this comment

JoeGruffins Apr 8, 2022

Choose a reason for hiding this comment

chappjc Apr 8, 2022

Choose a reason for hiding this comment

chappjc left a comment

Choose a reason for hiding this comment

chappjc commented Apr 15, 2022

JoeGruffins commented Mar 30, 2022 •

edited

JoeGruffins commented Mar 31, 2022 •

edited

JoeGruffins commented Apr 5, 2022 •

edited