Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Bridge continiously sending transactions with 'eth_sendTransaction timed out' message during stress testing #33

Open
akolotov opened this issue Mar 15, 2018 · 13 comments
Open

Bridge continiously sending transactions with 'eth_sendTransaction timed out' message during stress testing #33

akolotov opened this issue Mar 15, 2018 · 13 comments
Labels
bug critical rust to do

Comments

@akolotov
Copy link
Contributor

This is the issue is the same as paritytech/parity-bridge#149 but behavior is even worse due to automatic bridge restart implemented in POA bridge.

Network setup:

  • Home: a PoA testnet (Sokol)
  • Foreign: Ropsten

There are 1200 deposit transactions sent successfully to HomeBridge contract by a special python script. It took 8 blocks to validate all transactions.
https://sokol-explorer.poa.network/block/1418808
...
https://sokol-explorer.poa.network/block/1418815

The bridge discovered part of these transactions, tried to relay some of them, lost the connection and restarted:

INFO:bridge::bridge::deposit_relay: got 7 new deposits to relay
INFO:bridge::bridge::deposit_relay: relaying 7 deposits
INFO:bridge::bridge::deposit_relay: deposit relay completed
INFO:bridge::bridge::deposit_relay: got 129 new deposits to relay
INFO:bridge::bridge::deposit_relay: relaying 129 deposits
INFO:bridge::bridge::deposit_relay: deposit relay completed
INFO:bridge::bridge::withdraw_relay: got 0 new signed withdraws to relay
INFO:bridge::bridge::withdraw_relay: fetching messages and signatures
INFO:bridge::bridge::withdraw_relay: fetching messages and signatures complete
INFO:bridge::bridge::withdraw_relay: relaying 0 withdraws
INFO:bridge::bridge::withdraw_relay: relaying withdraws complete
INFO:bridge::bridge::withdraw_relay: waiting for signed withdraws to relay
INFO:bridge::bridge::withdraw_confirm: got 0 new withdraws to sign
INFO:bridge::bridge::withdraw_confirm: signing
INFO:bridge::bridge::withdraw_confirm: signing complete
INFO:bridge::bridge::withdraw_confirm: submitting 0 signatures
INFO:bridge::bridge::withdraw_confirm: submitting signatures complete
INFO:bridge::bridge::withdraw_confirm: waiting for new withdraws that should get signed
INFO:bridge::bridge::deposit_relay: got 113 new deposits to relay
INFO:bridge::bridge::deposit_relay: relaying 113 deposits
INFO:bridge::bridge::deposit_relay: deposit relay completed
INFO:bridge::bridge::deposit_relay: got 710 new deposits to relay
INFO:bridge::bridge::deposit_relay: relaying 710 deposits
WARN:bridge: Bridge is down with Request eth_sendTransaction timed out, attempting to restart
WARN:<unknown>: Sending a response to deallocated channel: Ok([Ok(String("0xc47e8427c9eda913b9749bf0904cd8765b39f5448368194cb7aa4330bbe6a44d"))])
WARN:<unknown>: Sending a response to deallocated channel: Ok([Ok(String("0x4d96f7f39c50dd7b19aac9af708bca450fb6c9fb6b72024c7736d9883614845d"))])
...
WARN:<unknown>: Sending a response to deallocated channel: Ok([Ok(String("0x6b16c0ef9e34d65c4431c4e1e8c043564d53cf3ce440d7ea706164838904e209"))])

The database file was not updated so the restart of the bridge thread caused the same error.

INFO:bridge::bridge::deposit_relay: got 951 new deposits to relay
INFO:bridge::bridge::deposit_relay: relaying 951 deposits
WARN:<unknown>: Sending a response to deallocated channel: Ok([Ok(String("0x9b034a82ebf6306933a35848f9d7b1552ababb8be5774e5501e4802013911a01"))])
WARN:<unknown>: Sending a response to deallocated channel: Ok([Ok(String("0x606b57af0b13dbeddf6b4c16833b0365dace777cc4feee82d2de14c5dde53c45"))])

So, the bridge is continuing to send transactions forever.

Even if the bridge process is killed manually, it is necessary to do manual modification of database but it causes lock of funds on HomeBridge contract side since incomplete amount of tokens is transfered by ForeignBridge contract.
@akolotov
Copy link
Contributor Author

The first of transactions arrived on Ropsten: https://ropsten.etherscan.io/tx/0x42d204dbf87b8b53c00a1ce11c79ed6eee91e189ebb1106211db7f24ba20f4b6.

The last transaction: https://ropsten.etherscan.io/tx/0xb53ea50e62bfcfda6ba1441d243a4df56f472b2e7d9b895943dbd8dcb8257d47.

Totally it was about 17000 txs sent by the bridge till it was killed.

@yrashk
Copy link
Contributor

yrashk commented Mar 16, 2018

On it

@akolotov
Copy link
Contributor Author

config.toml - https://gist.github.com/akolotov/5c68b9438c991401df12450ad569a4f2

@yrashk
Copy link
Contributor

yrashk commented Mar 16, 2018

Thank you Do you have a script that reproduces this issue?

@akolotov
Copy link
Contributor Author

https://github.com/poanetwork/parity-bridge-research/blob/master/erc20/bridge/contracts/home_batch_deposit.py

@akolotov
Copy link
Contributor Author

I think the root cause of the issue could relate to hardware on my testbed: it is an ordinary laptop with Intel i5-3317U CPU 1.70GHz, 4 cores, HDD (not SSD) and WiFi connection to Internet.
It is not my main workstation - it is dedicated just for tests: centos linux without X.org installed, parity, bridge - no other processes is being run.

@yrashk
Copy link
Contributor

yrashk commented Mar 17, 2018 •
edited
Loading

So, from the log above we can see that parity is actually sending a response to those timed out requests (bridge doesn't lose the connection, it simply abandons it after a timeout is experienced). The way bridge is structured it effectively considers timed out transactions to "never happen".

There are perhaps a couple of measures we can take here:

  1. Increase timeout length. This does not require changing bridge code, just the config. In your example config, it is set to 10 seconds. What's the longest reasonable timeout you can think of?
  2. Persist every outgoing transaction in a durable queue and always flush the queue before starting normal operations.
  3. Limit the number of transactions that can be sent out simultaneously to relieve the pressure on Parity and prevent the timeout counter from being started too early (timeout is per-transaction)

@yrashk
Copy link
Contributor

yrashk commented Mar 17, 2018

I think the most efficient first step on my end here would be (3). After that, we can do (2).

@akolotov
Copy link
Contributor Author

I completely agree with you thoughts. #1 is too platform specific and do not provide any guaranty that in some moment a system will not get in a state when the timeout is too short again.

yrashk added a commit to yrashk/parity-bridge that referenced this issue Mar 17, 2018
@yrashk
Problem: sending too many transactions
304a843 
When too many transactions are being sent out, the response
from the node comes after the operation has timed out.

This is particularly noticeable on heavy loads on slower
computers.

Solution: chunk transactions into batches

By default, the size of the batch is 2, however, it is important
to note that since there's no coordination between different
parties, there might be more than one batch at a time (but they
should be within a single digit since the number of operations
performed by bridge is limited)

Addresses omni#33
@yrashk
Copy link
Contributor

yrashk commented Mar 17, 2018

Would you mind trying yrashk@304a843 out on your hardware setup? This is a first draft. This change limits the size of the batch. The integration test pass. Let me know if this helps or not.

@akolotov
Copy link
Contributor Author

I have tested the changes with 1K and 2K deposits (transactions).
1K deposits transferred successfully.
The original issue was reproduced with 2K deposits.

Here is difference in bridge logs:
1K deposts:

INFO:bridge::bridge::deposit_relay: got 353 new deposits to relay
INFO:bridge::bridge::deposit_relay: relaying 353 deposits
INFO:bridge::bridge::deposit_relay: deposit relay completed
INFO:bridge::bridge::deposit_relay: got 300 new deposits to relay
INFO:bridge::bridge::deposit_relay: relaying 300 deposits
INFO:bridge::bridge::deposit_relay: deposit relay completed

2K deposts:

INFO:bridge::bridge::deposit_relay: got 710 new deposits to relay
INFO:bridge::bridge::deposit_relay: relaying 710 deposits
WARN:bridge: Bridge is down with Request eth_sendTransaction timed out, attempting to restart
WARN:<unknown>: Sending a response to deallocated channel: Ok([Ok(String("0x6c881ae94549f05a09088e1ed017324eb4909e9957d61f5ad9a4967a2ac04ad3"))])

So, the bridge combined two sequential blocks in one batch for the second test.

It means that it is makes sense to understand why Parity behaves differently in these two cases. Most probably we will see a proper fix for the issue in that case.

@yrashk yrashk mentioned this issue Mar 24, 2018
Closed
yrashk added a commit to yrashk/parity-bridge that referenced this issue Mar 24, 2018
@yrashk
Problem: sending too many transactions
7faa8c8 
When too many transactions are being sent out, the response
from the node comes after the operation has timed out.

This is particularly noticeable on heavy loads on slower
computers.

Solution: chunk transactions into batches

By default, the size of the batch is 2, however, it is important
to note that since there's no coordination between different
parties, there might be more than one batch at a time (but they
should be within a single digit since the number of operations
performed by bridge is limited)

Addresses omni#33
@yrashk
Copy link
Contributor

yrashk commented May 29, 2018

Do we still experience this issue in any severe form?

@akolotov
Copy link
Contributor Author

Did not test it with new version of bridge supporting RPC. Are you able to do generate traffic (dozen of transaction in one block) and test it by yourself?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug critical rust to do
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@yrashk @akolotov