Unknown error while processing xDai -> ETH transfer

[phahulin]

Today one more validator node was upgraded to the new version of oracle and it seems we have an error processing xDai -> ETH transactions.

I did a test with this tx: https://blockscout.com/poa/xdai/tx/0x79bc2884e340d7f7791e3296cc8da7bf4ef3ff6dcaacf8ef87f91fa7f1387965/internal_transactions

And it doesn't seem to be working because of an error during gas estimation:

Nov 18 13:33:44 {"level":30,"time":1574084023964,"msg":"Msg received with 1 Tx to send","name":"sender-home","v":1}
Nov 18 13:33:44 {"level":20,"time":1574084023964,"msg":"Reading nonce","name":"sender-home","v":1}
Nov 18 13:33:44 {"level":20,"time":1574084023965,"msg":"Nonce wasn't found in the DB","name":"sender-home","v":1}
Nov 18 13:33:44 {"level":20,"time":1574084023965,"msg":"Getting transaction count","name":"sender-home","module":"web3","address":"0x4D1c96B9A49C4469A0b720a22b74b034EDdFe051","v":1}
Nov 18 13:33:44 {"level":20,"time":1574084024004,"msg":"Transaction count obtained","name":"sender-home","module":"web3","address":"0x4D1c96B9A49C4469A0b720a22b74b034EDdFe051","transactionCount":2693,"v":1}
Nov 18 13:33:44 {"level":20,"time":1574084024004,"msg":"Sending 1 transactions","name":"sender-home","v":1}
Nov 18 13:33:44 {"level":30,"time":1574084024008,"msg":"Sending transaction with nonce 2693","name":"sender-home","v":1}
Nov 18 13:33:44 {"level":30,"time":1574084024825,"msg":"Tx generated 0x75ae4866a5bd30a5838e4e000f47cde86ec6b43ffba3b5140b0a6bd9480e7009 for event Tx 0x79bc2884e340d7f7791e3296cc8da7bf4ef3ff6dcaacf8ef87f91fa7f1387965","name":"sender-home","eventTransactionHash":"0x79bc2884e340d7f7791e3296cc8da7bf4ef3ff6dcaacf8ef87f91fa7f1387965","generatedTransactionHash":"0x75ae4866a5bd30a5838e4e000f47cde86ec6b43ffba3b5140b0a6bd9480e7009","v":1}
Nov 18 13:33:44 {"level":20,"time":1574084024825,"msg":"Updating nonce","name":"sender-home","v":1}
Nov 18 13:33:44 {"level":20,"time":1574084024827,"msg":"Finished processing msg","name":"sender-home","v":1}
Nov 18 13:33:44 {"level":20,"time":1574084024827,"msg":"Finished","name":"sender-home","v":1}

...

Nov 18 13:33:58 {"level":20,"time":1574084038234,"msg":"Getting block number","validator":"0x4D1c96B9A49C4469A0b720a22b74b034EDdFe051","name":"watcher-erc-native-collected-signatures","module":"web3","v":1}
Nov 18 13:33:58 {"level":20,"time":1574084038235,"msg":"Getting required block confirmations","validator":"0x4D1c96B9A49C4469A0b720a22b74b034EDdFe051","name":"watcher-erc-native-collected-signatures","module":"web3","contractAddress":"0x7301CFA0e1756B71869E93d4e4Dca5c7d0eb0AA6","v":1}
Nov 18 13:33:58 {"level":20,"time":1574084038259,"msg":"Block number obtained","validator":"0x4D1c96B9A49C4469A0b720a22b74b034EDdFe051","name":"watcher-erc-native-collected-signatures","module":"web3","blockNumber":6888195,"v":1}
Nov 18 13:33:58 {"level":20,"time":1574084038268,"msg":"Required block confirmations obtained","validator":"0x4D1c96B9A49C4469A0b720a22b74b034EDdFe051","name":"watcher-erc-native-collected-signatures","module":"web3","contractAddress":"0x7301CFA0e1756B71869E93d4e4Dca5c7d0eb0AA6","requiredBlockConfirmations":"1","v":1}
Nov 18 13:33:58 {"level":30,"time":1574084038268,"msg":"Getting past events","validator":"0x4D1c96B9A49C4469A0b720a22b74b034EDdFe051","name":"watcher-erc-native-collected-signatures","module":"web3","contractAddress":"0x7301CFA0e1756B71869E93d4e4Dca5c7d0eb0AA6","event":"CollectedSignatures","fromBlock":"6888194","toBlock":"6888194","v":1}
Nov 18 13:33:58 {"level":20,"time":1574084038298,"msg":"Past events obtained","validator":"0x4D1c96B9A49C4469A0b720a22b74b034EDdFe051","name":"watcher-erc-native-collected-signatures","module":"web3","contractAddress":"0x7301CFA0e1756B71869E93d4e4Dca5c7d0eb0AA6","event":"CollectedSignatures","count":1,"v":1}
Nov 18 13:33:58 {"level":30,"time":1574084038298,"msg":"Found 1 CollectedSignatures events","validator":"0x4D1c96B9A49C4469A0b720a22b74b034EDdFe051","name":"watcher-erc-native-collected-signatures","v":1}
Nov 18 13:33:58 {"level":20,"time":1574084038298,"msg":"Getting validator contract address","validator":"0x4D1c96B9A49C4469A0b720a22b74b034EDdFe051","name":"watcher-erc-native-collected-signatures","v":1}
Nov 18 13:33:58 {"level":20,"time":1574084038630,"msg":"Validator contract address obtained","validator":"0x4D1c96B9A49C4469A0b720a22b74b034EDdFe051","name":"watcher-erc-native-collected-signatures","validatorContractAddress":"0xe1579dEbdD2DF16Ebdb9db8694391fa74EeA201E","v":1}
Nov 18 13:33:58 {"level":20,"time":1574084038630,"msg":"Processing 1 CollectedSignatures events","validator":"0x4D1c96B9A49C4469A0b720a22b74b034EDdFe051","name":"watcher-erc-native-collected-signatures","v":1}
Nov 18 13:33:58 {"level":30,"time":1574084038631,"msg":"Processing CollectedSignatures 0x75ae4866a5bd30a5838e4e000f47cde86ec6b43ffba3b5140b0a6bd9480e7009","validator":"0x4D1c96B9A49C4469A0b720a22b74b034EDdFe051","name":"watcher-erc-native-collected-signatures","eventTransactionHash":"0x75ae4866a5bd30a5838e4e000f47cde86ec6b43ffba3b5140b0a6bd9480e7009","v":1}
Nov 18 13:33:58 {"level":20,"time":1574084038657,"msg":"Getting message signatures","validator":"0x4D1c96B9A49C4469A0b720a22b74b034EDdFe051","name":"watcher-erc-native-collected-signatures","eventTransactionHash":"0x75ae4866a5bd30a5838e4e000f47cde86ec6b43ffba3b5140b0a6bd9480e7009","v":1}
Nov 18 13:33:58 {"level":20,"time":1574084038657,"msg":"Getting message signature","validator":"0x4D1c96B9A49C4469A0b720a22b74b034EDdFe051","name":"watcher-erc-native-collected-signatures","eventTransactionHash":"0x75ae4866a5bd30a5838e4e000f47cde86ec6b43ffba3b5140b0a6bd9480e7009","index":0,"v":1}
Nov 18 13:33:58 {"level":20,"time":1574084038681,"msg":"Estimate gas","validator":"0x4D1c96B9A49C4469A0b720a22b74b034EDdFe051","name":"watcher-erc-native-collected-signatures","eventTransactionHash":"0x75ae4866a5bd30a5838e4e000f47cde86ec6b43ffba3b5140b0a6bd9480e7009","v":1}
Nov 18 13:33:59 {"level":20,"time":1574084039032,"msg":"Check if the message was already processed","validator":"0x4D1c96B9A49C4469A0b720a22b74b034EDdFe051","name":"watcher-erc-native-collected-signatures","module":"processCollectedSignatures:estimateGas","v":1}
Nov 18 13:33:59 {"level":20,"time":1574084039445,"msg":"Check if number of signatures is enough","validator":"0x4D1c96B9A49C4469A0b720a22b74b034EDdFe051","name":"watcher-erc-native-collected-signatures","module":"processCollectedSignatures:estimateGas","v":1}
Nov 18 13:34:00 {"level":20,"time":1574084040267,"msg":"Check that signature is from a validator","validator":"0x4D1c96B9A49C4469A0b720a22b74b034EDdFe051","name":"watcher-erc-native-collected-signatures","module":"processCollectedSignatures:estimateGas","address":"0x491FC792e78CDadd7D31446Bb7bDDef876a69AD6","v":1}
Nov 18 13:34:00 {"level":50,"time":1574084040600,"msg":"Unknown error while processing transaction","validator":"0x4D1c96B9A49C4469A0b720a22b74b034EDdFe051","name":"watcher-erc-native-collected-signatures","eventTransactionHash":"0x75ae4866a5bd30a5838e4e000f47cde86ec6b43ffba3b5140b0a6bd9480e7009","type":"Error","stack":"Error: Unknown error while processing message\n    at estimateGas (/mono/oracle/src/events/processCollectedSignatures/estimateGas.js:47:11)\n    at <anonymous>\n    at process._tickCallback (internal/process/next_tick.js:189:7)","v":1}
Nov 18 13:34:00 {"level":50,"time":1574084040623,"msg":"Unknown error while processing message","validator":"0x4D1c96B9A49C4469A0b720a22b74b034EDdFe051","name":"watcher-erc-native-collected-signatures","type":"Error","stack":"Error: Unknown error while processing message\n    at estimateGas (/mono/oracle/src/events/processCollectedSignatures/estimateGas.js:47:11)\n    at <anonymous>\n    at process._tickCallback (internal/process/next_tick.js:189:7)","v":1}
Nov 18 13:34:00 {"level":20,"time":1574084040623,"msg":"Finished","validator":"0x4D1c96B9A49C4469A0b720a22b74b034EDdFe051","name":"watcher-erc-native-collected-signatures","v":1}

Here is the .env file from the oracle

## General settings
ORACLE_BRIDGE_MODE=ERC_TO_NATIVE

## Home contract
COMMON_HOME_RPC_URL=https://dai.poa.network
COMMON_HOME_BRIDGE_ADDRESS=0x7301CFA0e1756B71869E93d4e4Dca5c7d0eb0AA6
ORACLE_HOME_RPC_POLLING_INTERVAL=5000

## Foreign contract
COMMON_FOREIGN_RPC_URL=https://mainnet.infura.io
COMMON_FOREIGN_BRIDGE_ADDRESS=0x4aa42145Aa6Ebf72e164C9bBC74fbD3788045016
ORACLE_FOREIGN_RPC_POLLING_INTERVAL=5000

## Gasprice
COMMON_HOME_GAS_PRICE_SPEED_TYPE=standard
COMMON_HOME_GAS_PRICE_FALLBACK=0
COMMON_HOME_GAS_PRICE_FACTOR=600000

COMMON_FOREIGN_GAS_PRICE_SUPPLIER_URL=https://gasprice.poa.network/
COMMON_FOREIGN_GAS_PRICE_SPEED_TYPE=standard
COMMON_FOREIGN_GAS_PRICE_FALLBACK=10000000000
ORACLE_FOREIGN_GAS_PRICE_UPDATE_INTERVAL=600000
COMMON_FOREIGN_GAS_PRICE_FACTOR=1

## Transport configuration
ORACLE_ALLOW_HTTP_FOR_RPC=no
ORACLE_QUEUE_URL=amqp://rabbit
ORACLE_REDIS_URL=redis://redis

ORACLE_HOME_START_BLOCK=6824455
ORACLE_FOREIGN_START_BLOCK=8934535

[akolotov]

It seems that the issue is due to this piece of the code:

https://github.com/poanetwork/tokenbridge/blob/f2a6a64637e607dffaee71df3694b012359218a0/oracle/src/events/processCollectedSignatures/index.js#L49

It initialize the array only with one element.

We see later in the log only one message when getting the signatures:

Nov 18 13:33:58 {"level":20,"time":1574084038657,"msg":"Getting message signature","validator":"0x4D1c96B9A49C4469A0b720a22b74b034EDdFe051","name":"watcher-erc-native-collected-signatures","eventTransactionHash":"0x75ae4866a5bd30a5838e4e000f47cde86ec6b43ffba3b5140b0a6bd9480e7009","index":0,"v":1}

and one log message when verify the signatures:

Nov 18 13:34:00 {"level":20,"time":1574084040267,"msg":"Check that signature is from a validator","validator":"0x4D1c96B9A49C4469A0b720a22b74b034EDdFe051","name":"watcher-erc-native-collected-signatures","module":"processCollectedSignatures:estimateGas","address":"0x491FC792e78CDadd7D31446Bb7bDDef876a69AD6","v":1}

[akolotov]

If this functionality is rolled back to

const requiredSignatures = []	
requiredSignatures.length = NumberOfCollectedSignatures	
requiredSignatures.fill(0)

the signatures are collected correctly and the withdrawal request is completed successfully.

[patitonar]

The reason why the following code was not working is because of how the Array constructor works

const requiredSignatures = new Array(NumberOfCollectedSignatures).fill(0) 

From the docs: A JavaScript array is initialized with the given elements, except in the case where a single argument is passed to the Array constructor and that argument is a number in this case it returns a new JavaScript array with its length property set to that number.

new Array(3) // [,,]

new Array('3') // ['3']

In our code, NumberOfCollectedSignatures is the type of string containing the number of collected signatures (for example '3') so the Array was initialized with only one element ['3'] and then changed to [0] when .fill(0) was called

In our previous code, internally it was correctly parsing the string to number when assigning the value to the length property

requiredSignatures.length = NumberOfCollectedSignatures

[akolotov]

Thanks Gerardo! So, it means that we have one more vote for having #63 to be addressed. With an e2e test when several validators are involved this behavior could be caught. Is this correct?

[patitonar]

Exactly, an e2e test with several validators would expose this incorrect behavior