"Max processing time reached" error

[gongf05]

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:

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

[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/

[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/

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
}

[ArseniiPetrovich]

@gongf05 Which linux distro do you use?

[gongf05]

@gongf05 Which linux distro do you use?

Hi I use MacOS 10.14.2

[rosulucian]

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

[jrainville]

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

[akolotov]

@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,

[jrainville]

@akolotov

Branch/commit: Master 7863197
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.

Hopefully the logs are clear enough.

Let me know if you need anything more.

[akolotov]

@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?

[jrainville]

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.

[akolotov]

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.

[jrainville]

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?

[iurimatias]

@akolotov any luck with this?

[akolotov]

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.

[patitonar]

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

[jrainville]

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.