token-bridge icon indicating copy to clipboard operation
token-bridge copied to clipboard

Published 20 hours ago • verified publisher icon omni

"Max processing time reached" error

Open gongf05 opened this issue 6 years ago • 16 comments

I had tried to test token bridge between Ropsten and Parity POA network. I had managed to deloy the contracts to both networks. The .env file for token bridge part is

BRIDGE_MODE=ERC_TO_ERC
HOME_POLLING_INTERVAL=5000
FOREIGN_POLLING_INTERVAL=1000
ALLOW_HTTP=no
HOME_RPC_URL=https://parity.poa/
FOREIGN_RPC_URL=https://ropsten.infura.io/
HOME_BRIDGE_ADDRESS=0x8442ee0081374b7f0001B5608c2BB5E4463F3b1A
FOREIGN_BRIDGE_ADDRESS=0x1DF15015F9f248F4227d9472C0002a146656B138
ERC20_TOKEN_ADDRESS=0x2713B4b73DACFb297Ec74a5e3040Bd0696Dbe9f9

VALIDATOR_ADDRESS=XXX
VALIDATOR_ADDRESS_PRIVATE_KEY=XXX


QUEUE_URL=amqp://127.0.0.1
REDIS_URL=redis://127.0.0.1:6379
REDIS_LOCK_TTL=1000

HOME_START_BLOCK=
FOREIGN_START_BLOCK=

LOG_LEVEL=debug
MAX_PROCESSING_TIME=20000

#testing accs
USER_ADDRESS=XXX
USER_ADDRESS_PRIVATE_KEY=XXX
HOME_MIN_AMOUNT_PER_TX=1
FOREIGN_MIN_AMOUNT_PER_TX=1
HOME_TEST_TX_GAS_PRICE=10000000000
FOREIGN_TEST_TX_GAS_PRICE=10000000000

I tried to run docker-compose run bridge npm run watcher:signature-request and found error as:

token-bridge_ -bash _171x47

Is there anyone find a similar issue and any suggestion would be appreciated. Thanks!

gongf05 avatar Dec 11 '18 15:12 gongf05

I cannot access to https://parity.poa from my system by using

curl -s -X POST -H "Content-Type:application/json" -d '{"jsonrpc":"2.0","method":"eth_blockNumber", "params":[],"id":666}' https://parity.poa/

akolotov avatar Dec 11 '18 15:12 akolotov

I cannot access to https://parity.poa from my system by using

curl -s -X POST -H "Content-Type:application/json" -d '{"jsonrpc":"2.0","method":"eth_blockNumber", "params":[],"id":666}' https://parity.poa/

Thanks for quick response. The link is https://nile.dev-ocean.com (sorry for not including the real link)

Below is the tx info:

$ curl -s -X POST --data '{"jsonrpc":"2.0","method":"eth_getTransactionByHash","params":["0x5f3e47e313fb1acbace89de5456785387bce860672aba9f60f296abcce7233f6"],"id":1}' -H "Content-Type: application/json" 52.1.94.55:8545 | jq
{
  "jsonrpc": "2.0",
  "result": {
    "blockHash": null,
    "blockNumber": null,
    "chainId": "0x2323",
    "condition": null,
    "creates": null,
    "from": "0x0e364eb0ad6eb5a4fc30fc3d2c2ae8ebe75f245c",
    "gas": "0x44a9a",
    "gasPrice": "0x2540be400",
    "hash": "0x5f3e47e313fb1acbace89de5456785387bce860672aba9f60f296abcce7233f6",
    "input": "0x995b2cff0000000000000000000000000e364eb0ad6eb5a4fc30fc3d2c2ae8ebe75f245c0000000000000000000000000000000000000000000000000de0b6b3a7640000cb3f7ba3352f77081d5d52dd0f2d6af81c7424f5366a5ec933fe4257eb2b88c0",
    "nonce": "0x48",
    "publicKey": "0xd73905a85de3ea9686618e5034c73dfe5f6b24a477514726b8a0a581cbcdbca091df840ea7c88e047d939c0a86dbee3514726e8892c7960aba8853dcc3b0565e",
    "r": "0xa6bb22b7e82f0d05f03a118f77ad0d81a8b9ef988564eb1bb994a7b19b2ae8c3",
    "raw": "0xf8cc488502540be40083044a9a94642339c00133e27e6021968dd9e8304f9fab734880b864995b2cff0000000000000000000000000e364eb0ad6eb5a4fc30fc3d2c2ae8ebe75f245c0000000000000000000000000000000000000000000000000de0b6b3a7640000cb3f7ba3352f77081d5d52dd0f2d6af81c7424f5366a5ec933fe4257eb2b88c0824669a0a6bb22b7e82f0d05f03a118f77ad0d81a8b9ef988564eb1bb994a7b19b2ae8c3a053e15f0806b30399d63890783880f61bad387c6040afd231a044f047ca025b4d",
    "s": "0x53e15f0806b30399d63890783880f61bad387c6040afd231a044f047ca025b4d",
    "standardV": "0x0",
    "to": "0x642339c00133e27e6021968dd9e8304f9fab7348",
    "transactionIndex": null,
    "v": "0x4669",
    "value": "0x0"
  },
  "id": 1
}

gongf05 avatar Dec 11 '18 17:12 gongf05

@gongf05 Which linux distro do you use?

ArseniiPetrovich avatar Dec 19 '18 21:12 ArseniiPetrovich

@gongf05 Which linux distro do you use?

Hi I use MacOS 10.14.2

gongf05 avatar Dec 19 '18 22:12 gongf05

I had this issue as well and tried to change the MAX_PROCESSING_TIME var without success.

As far as i can tell this is caused by the fact that the calls to the node url don`t get a response and the containers hangs waiting until MAX_PROCESSING_TIME is reached and the get shut down.

In my case, I was trying to hit a local ganache node and i had the node url set like FOREIGN_RPC_URL=http://localhost:8546 and the bridge started working when i switched the url to http://host.docker.internal:8546

rosulucian avatar Mar 06 '19 04:03 rosulucian

I have the same issue. I tried increasing the MAX_PROCESSING_TIME, but all it did was causing another error in the sender-home process:

[1556816879419] INFO  (sender-home): Connected to redis
[1556816879432] INFO  (sender-home): Connected to amqp Broker
[1556816879555] DEBUG (sender-home): Chain id obtained
    module: "web3"
    chainId: 77
[1556816879569] INFO  (sender-home): Msg received with 1 Tx to send
[1556816879569] DEBUG (sender-home): Acquiring lock
[1556816879580] DEBUG (sender-home): Gas price updated using the oracle
    module: "gasPrice"
    gasPrice: "4400000000"
[1556816976277] ERROR (LockError): Exceeded 200 attempts to lock the resource "lock:home:nonce".
    LockError: Exceeded 200 attempts to lock the resource "lock:home:nonce".
        at C:\dev\bridge-oracle\node_modules\redlock\redlock.js:342:20
        at tryCatcher (C:\dev\bridge-oracle\node_modules\bluebird\js\release\util.js:16:23)
        at Promise.errorAdapter [as _rejectionHandler0] (C:\dev\bridge-oracle\node_modules\bluebird\js\release\nodeify.js:35:34)
        at Promise._settlePromise (C:\dev\bridge-oracle\node_modules\bluebird\js\release\promise.js:566:21)
        at Promise._settlePromise0 (C:\dev\bridge-oracle\node_modules\bluebird\js\release\promise.js:614:10)
        at Promise._settlePromises (C:\dev\bridge-oracle\node_modules\bluebird\js\release\promise.js:690:18)
        at _drainQueueStep (C:\dev\bridge-oracle\node_modules\bluebird\js\release\async.js:138:12)
        at _drainQueue (C:\dev\bridge-oracle\node_modules\bluebird\js\release\async.js:131:9)
        at Async._drainQueues (C:\dev\bridge-oracle\node_modules\bluebird\js\release\async.js:147:5)
        at Immediate.Async.drainQueues [as _onImmediate] (C:\dev\bridge-oracle\node_modules\bluebird\js\release\async.js:17:14)
        at runCallback (timers.js:705:18)
        at tryOnImmediate (timers.js:676:5)
        at processImmediate (timers.js:658:5)

FYI, I use the npm processes because the Docker container wasn't able to connect to RabbitMQ. Using npm, I got it to connect to Redis and RabbitMQ and most of the transfer worked, except for the last part implicating the sender:home.

Here is my .env file (with keys and ID removed):

BRIDGE_MODE=ERC_TO_ERC
HOME_POLLING_INTERVAL=1000
FOREIGN_POLLING_INTERVAL=1000
ALLOW_HTTP=yes
HOME_RPC_URL=https://sokol.poa.network
FOREIGN_RPC_URL=https://rinkeby.infura.io/INFURA_ID
HOME_BRIDGE_ADDRESS=0xF2c3d630c95832dCB08D5Eafd855ab923E0FC33c
FOREIGN_BRIDGE_ADDRESS=0x1eBc6838720B18FF8C000826F2bDD9491209b09A
ERC20_TOKEN_ADDRESS=0x2a82C4e6a7cfFEf6a5C3D15E60ee7502083C4c4f

VALIDATOR_ADDRESS=0xf21665506D08b58d2D8A1419F981B1E822bF9C19
VALIDATOR_ADDRESS_PRIVATE_KEY=PRIVATE_KEY

HOME_GAS_PRICE_ORACLE_URL=https://gasprice.poa.network/
HOME_GAS_PRICE_SPEED_TYPE=standard
HOME_GAS_PRICE_FALLBACK=1000000000
HOME_GAS_PRICE_UPDATE_INTERVAL=600000

FOREIGN_GAS_PRICE_ORACLE_URL=https://gasprice.poa.network/
FOREIGN_GAS_PRICE_SPEED_TYPE=standard
FOREIGN_GAS_PRICE_FALLBACK=1000000000
FOREIGN_GAS_PRICE_UPDATE_INTERVAL=600000

QUEUE_URL=amqp://127.0.0.1
REDIS_URL=redis://127.0.0.1:6379
REDIS_LOCK_TTL=1000

HOME_START_BLOCK=8476249
FOREIGN_START_BLOCK=4312290

LOG_LEVEL=info
MAX_PROCESSING_TIME=200000

Do you think it's related to the FOREIGN_RPC_URL as well? Since I'm not in a docker env and since it's not localhost, it shouldn't have a problem, no?

Here are my System Specs: OS: Windows 10 Node: v10.13.0 NPM: 6.4.1 Oracle version: Latest master by the date of this post

Thanks

jrainville avatar May 02 '19 20:05 jrainville

@jrainville I see two issues here:

  1. Impossibility to connect to RabbitMQ by using the token bridge oracle run in the docker environment.
  2. Issue with locking resources in the Redis DB during the oracle operations.

First of all could you specify exact branch/commit of the token bridge repo you cloned?

Next, for the first issue could you provide the .env file and the entire docker logs produced after the oracle run?

And could you also provide entire log for the issue with the Redis DB: starting from the oracle run till the moment when the issue happens.

Thanks,

akolotov avatar May 16 '19 14:05 akolotov

@akolotov

Branch/commit: Master https://github.com/poanetwork/token-bridge/commit/786319775ddadf655b89079c7c104f89d961d5e7 Again, I'm on Windows, do you know if that could be the cause?

  • Env file: https://gist.github.com/jrainville/e27ff3db120f2625d27b1040162fcd81

  • Contract env file just in case: https://gist.github.com/jrainville/0de05feaee39ce2a55f62b331572dc7e

  • Docker logs: https://gist.github.com/jrainville/235bea77b8f40001fd3288e0214bd729

    • Somehow Redis doesn't work anymore. It used to after I had installed locally, but it gives me the same issue as RabbitMQ now.

  • Logs for everything when I start using npm run dev and Redis and RabbitMQ in separate processes: https://gist.github.com/jrainville/c1df547c595beccc098e19c576b15287

This is what I have in the UI, it gets stuck at this step. image

Hopefully the logs are clear enough.

Let me know if you need anything more.

jrainville avatar May 16 '19 16:05 jrainville

@jrainville hi!

In your docker logs I see that RabitMQ container was not started at all. Could it be a windows specific issue since we use the docker volumes to keep the MQ data on disk in case of the container restart:

https://github.com/poanetwork/token-bridge/blob/adb29317b070f620ee5749b54272f822b6446e3d/docker-compose.yml#L3-L16

From your logs that are got after start by NPM I see that you enabled 'INFO' logs verbosity could you extend it to DEBUG (in .env file)? It will allow us to see more information what happens on your system. It is quite interesting to see if the issue is with getting nonce by sender only or we have an issue with writing the last processed blocks to the redis db as well. For this, could you use redis-cli command with GET command to check if values of keys that ended with lastProcessedBlock are being increased during the token bridge watchers operations?

akolotov avatar May 24 '19 16:05 akolotov

Hi @akolotov ,

I reran npm run dev with loglevel at debug. It did get a lot more info, so I isolated the sender home logs just in case.

I didn't re-attempt a transfer of tokens, as the last one seemed still in the "queue" (Msg received with 1 Tx to send)

As for using redis-cli, I never used it before, so I'm not sure what I need to input in it. I see that my lastProcessedBlock is 4439158, but I don't know how to get the keys for that, as I don't know the name of the keys. I tried GET 4439158 to no avail.

Let me know what command to enter and I'll quickly give you the output.

jrainville avatar May 24 '19 17:05 jrainville

Examples of the command parameters could be found here: https://github.com/poanetwork/token-bridge/tree/master#redis. I am interested to see the output in dynamic - e.g. you run the bridge oracle, run redis-cli, wait for 2-3 minutes, run redis-cli again.

akolotov avatar May 24 '19 21:05 akolotov

Sorry, I just noticed I didn't paste my gist last time. Here it is: https://gist.github.com/jrainville/81b062670ceac9388146b83d33554ceb

I tried the redis-cli command, but it keeps returning (nil):

C:\WINDOWS\system32>redis-cli GET signature-request:lastProcessedBlock
(nil)

C:\WINDOWS\system32>redis-cli GET signature-request:lastProcessedBlock
(nil)

C:\WINDOWS\system32>redis-cli GET signature-request:4455470
(nil)

C:\WINDOWS\system32>redis-cli GET signature-request:8903450
(nil)

C:\WINDOWS\system32>redis-cli GET signature-request:4455465
(nil)

C:\WINDOWS\system32>redis-cli
redis 127.0.0.1:6379> GET signature-request:lastProcessedBlock
(nil)
redis 127.0.0.1:6379> GET signature-request:lastProcessedBlock
(nil)
redis 127.0.0.1:6379> GET signature-request:"4455465"
(nil)
redis 127.0.0.1:6379> GET signature-request:4455465
(nil)

So either I'm doing something wrong, or Redis doesn't store anything. Is there a way to get the DB state or see if it actually contains anything?

jrainville avatar May 27 '19 12:05 jrainville

@akolotov any luck with this?

iurimatias avatar Jun 10 '19 11:06 iurimatias

Thanks for detailed logs

First of all I see that the Redis could be updated with new block values in the watchers whereas the code cannot lock a resource from the sender. That's very strange.

Could you stop redis, find redisbd files on the disk, remove them and start redis?

Is it possible for you try to run the bridge oracle on a Linux machine? I am worrying if it could windows specific.

akolotov avatar Jun 10 '19 18:06 akolotov

Is there a way to get the DB state or see if it actually contains anything?

You can run command KEYS * on redis-cli to get all the keys that have a value. Then GET <key> to get the value for that key.

From the error log, it seems that key lock:home:nonce is defined on redis. Please try to remove that key using command DEL lock:home:nonce or to delete all keys run FLUSHALL

patitonar avatar Jun 10 '19 18:06 patitonar

I had one of my colleagues test with a Linux machine and even though he ran in the same issue as me using Docker, once using the yarn/npm commands, he manages to make it work. Transfers from and to the child network worked for him.

He used the same exact env files as I so the only conclusion is that there is an issue running the bridge-oracle in Windows.

Thanks for taking the time to try to debug this with me.

jrainville avatar Jun 19 '19 13:06 jrainville