search

raiden-network / scenario-player

MIT License
1 stars 16 forks source link

Transaction [txhash] failed #238

Closed czepluch closed 5 years ago

czepluch commented 5 years ago

Description

Today when trying to start a new scenario I run into the error shown in the attached logfile. scenario-player-run_pfs7_multiple_payments_2019-08-15T16:54:56.log

It seems that a tx fails when trying to call deposit in the UDC contract. The problem also happens on old scenarios that I've run earlier today.

I tried installing the SP in a fresh venv too, but the problems persists.

This is on latest dev branch of the SP and of Raiden.

Expected Behavior

I expected the SP to start the scenario as usual and to fund the nodes correctly.

czepluch commented 5 years ago

Tried to use both the bb eth node vpn and my dappcon node, but same problem occurs.

eorituz commented 5 years ago

I can't reproduce the error. Your error code points to a reverted onchain Tx No clue what goes wrong here, but it works fine for me atm.

Dominik1999 commented 5 years ago

I reproduced the error. I first successfully ran a scenario, then, when I simply want to re-run it, I get the same error. 

{
  "result": "scenario error",
  "event": "Run finished",
  "logger": "scenario_player.main",
  "level": "error",
  "timestamp": "2019-08-16 09:46:51.021767",
  "exception": "
  Traceback (most recent call last):
  File \"/home/pirate/PycharmProjects/ScenarioPlayer/scenario-player/scenario_player/main.py\", line 179, in run
  runner.run_scenario()
  File \"/home/pirate/PycharmProjects/ScenarioPlayer/scenario-player/scenario_player/runner.py\", line 224, in run_scenario
  wait_for_txs(self.client, fund_tx | ud_token_tx | mint_tx)
  File \"/home/pirate/PycharmProjects/ScenarioPlayer/scenario-player/scenario_player/utils/legacy.py\", line 193, in wait_for_txs
  raise ScenarioTxError(f\"Transaction {encode_hex(txhash)} failed.\")
  scenario_player.exceptions.legacy.ScenarioTxError: Transaction 0xe8195f306388726e7810eb84d5e1e1bac96fc884eb67ad13fc3c09998bbd77e3 failed."
}

Now it constantly fails with this error

eorituz commented 5 years ago

@Dominik1999 That's wired since your "first" deposit Tx went through (https://goerli.etherscan.io/tx/0xb74dcdfa5820bbf9d2bf38b395c5eb83e6808f0d7ed505ca22a2b548d1d58156) but the second one failed. Which scenario did you run?

Edit: Ok I'll try to reproduce it as well and have a look

Dominik1999 commented 5 years ago

I ran https://github.com/raiden-network/raiden/pull/4619/files

but it also happens with any other scenario now. Probably the deposit is not increasing, because the SP uses the same nodes (Eth addresses) and tries to deposit as defined in the scenario

one of these require() isn't fulfilled probably.

function deposit(address beneficiary, uint256 new_total_deposit)
        external
    {
        require(new_total_deposit > total_deposit[beneficiary], "deposit not increasing");

        // Calculate the actual amount of tokens that will be transferred
        uint256 added_deposit = new_total_deposit - total_deposit[beneficiary];

        balances[beneficiary] += added_deposit;
        total_deposit[beneficiary] += added_deposit;

        // Update whole_balance, but take care against overflows.
        require(whole_balance + added_deposit >= whole_balance, "overflowing deposit");
        whole_balance += added_deposit;

        // Decline deposit if the whole balance is bigger than the limit.
        require(whole_balance <= whole_balance_limit, "too much deposit");

        // Actual transfer.
        require(token.transferFrom(msg.sender, address(this), added_deposit), "tokens didn't transfer");
eorituz commented 5 years ago

Mhh I still can't reproduce the error. Not even if I reuse already used addresses on purpose... @Dominik1999 could you provide me with the exact command you ran as well as the content of your ~./raiden/scenario-player/scenarios/pfs7_multiple_payments folder?

eorituz commented 5 years ago

I even ran the scenario without any trouble even though I used previously used Addresses on purpose... Edit: (Since we're always deploying a new token for every run there should be no conflict with already existing balances in any SC.)

czepluch commented 5 years ago

@Dominik1999 what you explain is exactly what happened to me too.

deepbrook commented 5 years ago

Running scenarios on 0.3.1, I cannot reproduce this locally.

Dominik1999 commented 5 years ago

here are my logs @eorituz

I can reproduce it every time

Test-Fails-Transaction-UDC.zip

eorituz commented 5 years ago

Since I won't be able to fix it until Wednesday, I'll unassign me for now.

eorituz commented 5 years ago

So apparently we still have trouble with deposit function calls. Some of them fail with no obvious pattern.

You can check my tx history here. All Tx in block 1209528 & 1209530 belong to one scenario player run. (Only one deposit fails) Another player-run are the Tx in block 1209685 and 1209686. (Three deposits fail)

@hackaugusto could you please also have a look at it?

hackaugusto commented 5 years ago

The initial comment has the following stacktrace:

Traceback (most recent call last):
  File "/home/jacob/dev/venvs/sp_venv/lib/python3.7/site-packages/scenario_player/main.py", line 179, in run
    runner.ru
n_scenario()
  File "/home/jacob/dev/venvs/sp_venv/lib/python3.7/site-packages/scenario_player/runner.py", line 224, in run_scenario
    wait_for_txs(self.client, fund_tx |
ud_token_tx | mint_tx)
  File "/home/jacob/dev/venvs/sp_venv/lib/python3.7/site-packages/scenario_player/utils/legacy.py", line 193, in wait_for_txs
    raise ScenarioTxErro
r(f"Transaction {encode_hex(txhash)} failed.")
scenario_player.exceptions.legacy.ScenarioTxError: Transaction 0xb508c34739260b6031e96deed105783edc0306c9b7addbe470789656c2f91c
e4 failed.

Transaction details

desc value
tx.hash 0xb508c34739260b6031e96deed105783edc0306c9b7addbe470789656c2f91c
mined at block 1124179
msg.sender 0x0bae0289AAA26845224F528F9B9DefE69e01606E
UserDeposit address 0xdE6c9977D903Ff978E24f06DC4d78FA49486094E
Token address 0x2D64D0d6C3892f58B7698C8520ba12ee02998F00
function deposit
beneficiary 0x263726Baa4606153cEc023fd294E55e15ec391B5
new_total_deposit 5000

These are the requires for the deposit function:

        require(new_total_deposit > total_deposit[beneficiary], "deposit not increasing");
        require(whole_balance + added_deposit >= whole_balance, "overflowing deposit");
        require(whole_balance <= whole_balance_limit, "too much deposit");
        require(token.transferFrom(msg.sender, address(this), added_deposit), "tokens didn't transfer");

And these are the requires for the transferFrom:

        require(balances[_from] >= _value);
        require(allowed[_from][msg.sender] >= _value);
        require(_value > 0);

I used the following setup:

from web3 import HTTPProvider, Web3
from raiden_contracts.contract_manager import ContractManager, contracts_precompiled_path
from raiden_contracts.constants import CONTRACT_CUSTOM_TOKEN, CONTRACT_USER_DEPOSIT
from eth_utils import to_checksum_address

url ='<redacted>'

web3 = Web3(HTTPProvider(url))
contract_manager = ContractManager(contracts_precompiled_path())
ud = web3.eth.contract(abi=contract_manager.get_contract_abi(CONTRACT_USER_DEPOSIT), address='0xdE6c9977D903Ff978E24f06DC4d78FA49486094E')
token = web3.eth.contract(abi=contract_manager.get_contract_abi(CONTRACT_CUSTOM_TOKEN), address=ud.functions.token().call())

And executed the following queries:

>>> ud.functions.total_deposit('0x263726Baa4606153cEc023fd294E55e15ec391B5').call(block_identifier=1124179)
0
>>> ud.functions.whole_balance().call(block_identifier=1124179)
47000000000000004041000
>>> ud.functions.whole_balance_limit().call(block_identifier=1124179)
115792089237316195423570985008687907853269984665640564039457584007913129639935
>>> token.functions.balanceOf('0x0bae0289AAA26845224F528F9B9DefE69e01606E').call(block_identifier=1124179)
0
>>> token.functions.allowance('0x0bae0289AAA26845224F528F9B9DefE69e01606E', '0xdE6c9977D903Ff978E24f06DC4d78FA49486094E').call(block_identifier=1124179)
15000

So, the problem is that the address 0x0bae0289AAA26845224F528F9B9DefE69e01606E doesn't have any tokens to transfer.

eorituz commented 5 years ago

@hackaugusto I think there is a misunderstanding. In Jacobs code the Token is "0xb06bA27e1cc31aa7d16f0B9303Da6Bf23885Fd7F". And the beneficiary does have 10.000 of those tokens. The Token Address thing that you pulled out of the logs is something else (pls don't ask me what it is :D )

hackaugusto commented 5 years ago

So, I followed the logs, and the scenario player is calling the mint function, turns out the address had a balance of 10000 until the block 1124178. At the block 1124179 the following happened:

from web3.utils.abi import filter_by_type
from eth_utils import event_abi_to_log_topic
from web3.utils.events import get_event_data
topic_to_event_abi = {event_abi_to_log_topic(event_abi): event_abi for event_abi in filter_by_type('event', token.events.abi)}
[get_event_data(topic_to_event_abi[log['topics'][0]], log) for log in web3.eth.getLogs({'address': '0x2D64D0d6C3892f58B7698C8520ba12ee02998F00', 'fromBlock': 1124178, 'toBlock': 1124190})]

The above prints:

[AttributeDict({'args': AttributeDict({'_from': '0x0bae0289AAA26845224F528F9B9DefE69e01606E', '_to': '0xdE6c9977D903Ff978E24f06DC4d78FA49486094E', '_value': 5000}), 'event': 'Transfer', 'logIndex': 44, 'transactionIndex': 44, 'transactionHash': HexBytes('0x926a169a3dd41b99d1db7709bda3410bd24695d19268de28de2dbdafe4dbb5c0'), 'address': '0x2D64D0d6C3892f58B7698C8520ba12ee02998F00', 'blockHash': HexBytes('0xc871d5fff14637cbbcf4a07e2ca4eb1f274f9a49de8bddd8c992cc37fc3d1e76'), 'blockNumber': 1124179}),
 AttributeDict({'args': AttributeDict({'_from': '0x0bae0289AAA26845224F528F9B9DefE69e01606E', '_to': '0xdE6c9977D903Ff978E24f06DC4d78FA49486094E', '_value': 5000}), 'event': 'Transfer', 'logIndex': 46, 'transactionIndex': 46, 'transactionHash': HexBytes('0xf6e550196aa35cab2cccb22d2346e834963082138487acef4ae87baa3a0822ac'), 'address': '0x2D64D0d6C3892f58B7698C8520ba12ee02998F00', 'blockHash': HexBytes('0xc871d5fff14637cbbcf4a07e2ca4eb1f274f9a49de8bddd8c992cc37fc3d1e76'), 'blockNumber': 1124179})]

Transactions:

status txidx txhash
success 44 0xf6e550196aa35cab2cccb22d2346e834963082138487acef4ae87baa3a0822ac
success 46 0x926a169a3dd41b99d1db7709bda3410bd24695d19268de28de2dbdafe4dbb5c0
revert 50 0xb508c34739260b6031e96deed105783edc0306c9b7addbe470789656c2f91ce4

So it makes sense for the third one to fail.

hackaugusto commented 5 years ago

@eorituz I pulled the address directly from the user deposit smart contract, calling ud.functions.token().call()

eorituz commented 5 years ago

@hackaugusto thanks, that makes sense... So to me, it looks like something more fundamental is broken. The handling around when which, for whom and how much tokens should be minted. (During the PFS7 scenario run e.g. plenty of tokens get minted but never used?)

hackaugusto commented 5 years ago

~@ulope found the problem~

~The problem is that Contract.mint uses self.config.token.max_funding - balance, while UserDepositContract.deposit uses self.config.settings.services.udc.token.balance_per_node~

~The first defaults to DEFAULT_TOKEN_BALANCE_FUND = 10_000, while the second is set in the scenario to balance_per_node: 20000~

Edit: It was close, but not the exact problem in the issue. The balance_per_node was not set, it used the default of 5_000. Nevertheless there are 5 nodes that need a deposit of 5_000 but only 10_000 are minted, the code has to be changed to mint the amount of tokens required proportionally to the number of nodes.

Edit, some updates based on the dev branch:

~self.config.token.max_funding defaults to 50_000 tokens.~ (These values are not important)

General workflow of the scenario player:

The call to UserDepositContract.mint delegates to Contract.mint, which does the following:

https://github.com/raiden-network/scenario-player/blob/0701bb986f47e1ec4a4fb7a469157826da1993e2/scenario_player/utils/token.py#L71-L86

Relevant logs for the allowance/mint/deposit (note that the first two entries are for the allowance, the use of the deposit word is a typo)

christianbrb commented 5 years ago

From a timing perspective this could have been introduced by https://github.com/raiden-network/scenario-player/pull/221 released with https://github.com/raiden-network/scenario-player/releases/tag/v0.3.0

eorituz commented 5 years ago

@hackaugusto Here's a proper problem description.

So Here's the deal:

I ran this scenario pfs7_multiple_payments.zip it's basically the same as jacob suggested but with settings.services.udc.token.balance_per_node = token.balance_min = 20000

Scenario player command

scenario_player --chain goerli:http://geth.goerli.ethnodes.brainbot.com:8545 run --keystore-file keystore/UTC--1  --password 123 --no-ui /home/oliver/Arbeit/github/scenario-player/test_scenarios/pfs7_multiple_payments.yaml

Scenario player version

Should be latest Dev 

(scenario_player) oliver@bbpc:~/Arbeit/github/scenario-player$ git log
commit 60b359899a3385d82e2d71da8f57dacce8789111 (HEAD -> dev, upstream/dev, origin/dev)
Author: DevOpsBot <contact@brainbot.li>
Date:   Fri Aug 23 08:04:57 2019 +0000

    'Sync Branch Versions.'

Raiden version

(scenario_player) oliver@bbpc:~/Arbeit/github/scenario-player$ raiden version
{
  "raiden": "0.100.5.dev3+g3a6642643",
  "raiden_db_version": 23,
  "python_implementation": "CPython",
  "python_version": "3.7.1",
  "system": "Linux 64bit_ELF 4.15.0-58-generic",
  "architecture": "x86_64",
  "distribution": "source"
}

Scenario player logs

logs_tx_failed.zip

Fancy remark

If I set the ~/.raiden/scenario-player/scenarios/pfs7/run_number.txt value to 1 I face another problem. (The run_number is used to generate the deterministic priv keys of the nodes. So I "reused" nodes on purpose)

scenario_player.exceptions.legacy.ScenarioError: Failed to start Raiden node 0

Logs: logs_failed_to_start_raien.zip

I'm not sure if it is related or an issue on it's own...

ulope commented 5 years ago

Seems @hackaugusto found the issue.

Contract.balance (which is inherited by Token and UserDepositContract) is querying the account's eth balance not the token balance: https://github.com/raiden-network/scenario-player/blob/3f87cc464cf8974a3ac69acc6266336d5edd70ac/scenario_player/utils/token.py#L39-L40

275 corrects this. A brief local test seems to confirm that the txs now are preformed correctly.

hackaugusto commented 5 years ago

The scenario player logs don't have enough information for me to pin down exactly what happened. So I fetched all logs from the smart contract:

from collections import defaultdict
from eth_utils import to_hex

token_address = '0x2D64D0d6C3892f58B7698C8520ba12ee02998F00'
scenario_node_address = '0x0bae0289AAA26845224F528F9B9DefE69e01606E'
deployed_at = 1008864
testing_up_to = 1124190
sender_transaction = defaultdict(list)
hash_to_log = defaultdict(list)
all_logs = web3.eth.getLogs({'address': token_address, 'fromBlock': deployed_at, 'toBlock': testing_up_to})
decoded_logs = [get_event_data(topic_to_event_abi[log['topics'][0]], log) for log in all_logs]
transactions = [web3.eth.getTransaction(l['transactionHash']) for l in decoded_logs]
for t in transactions:
  sender_transaction[t['from']].append(t)

for l in decoded_logs:
  hash_to_log[l['transactionHash']].append(l)

events_from_scenario = [hash_to_log[t['hash']] for t in sender_transaction[scenario_node_address]]

result = 0
for t, h, v in [(e['event'], e['transactionHash'], e['args'].get('_value') or e['args'].get('_num')) for e in events_from_scenario]:
   if t == 'Transfer': result -= v
   if t == 'Minted': result += v
   print(result, to_hex(result))

result is 0, here are the events.

Here are the balances of interest for the corresponding run (The same address was used multiple times, it first minted 500000 tokens and gradually this balance decreased, until tests runs to fail):

function balance tx_hash
approve 0 0x847223ba1edde49c9d8cfe6bbb944f832527a3b25d230ec1efd175bd538ca3d6
mintFor 10000 0x53864d0566f21165a717f79ce9e3ddd224e2e6ea8af24fe4b4df9370cefb5940
deposit 5000 0x926a169a3dd41b99d1db7709bda3410bd24695d19268de28de2dbdafe4dbb5c0
deposit 0 0xf6e550196aa35cab2cccb22d2346e834963082138487acef4ae87baa3a0822ac

The important thing is that the hashes match above match the ones from above. And now its known all the transactions for the given scenario run.

hackaugusto commented 5 years ago

Okay, I found the problem. The explanation bellow assumes the code from v0.3.0-dev (this is important because of the values in the constants.py):

The solution here should be simple, just like update allowance, a update mint of sort has to be introduced, and replace the call to mint that is not enough.