BF1 scenario failed - Githubissues

rakanalh commented 4 years ago

Last night's SP run failed. Debug and figure out issues

Issue checklist

[ ] Investigate the failure by going through the run logs
[ ] Write a unit / integration test to simulate the issue
[ ] Fix
[ ] Re-run scenarios to make sure the problem is fixed

agatsoh commented 4 years ago

I am running a variant of the bf1_basic_functionality scenario in which i use a different matrix server for each node. The scenario gist as well as all associated logs are attached in these links.

christianbrb commented 4 years ago

The scenario @agatsoh is running is a different one (hidden the comment https://github.com/raiden-network/raiden/issues/4990#issuecomment-535852757)

LefterisJP commented 4 years ago

isn't it the same exact scenario just with different matrix servers as per his comment?

LefterisJP commented 4 years ago

From the logs this is the assertion error:

{"task": "<AssertBlockchainEventsTask: {'contract_name': 'TokenNetwork', 'event_name': 'NonClosingBalanceProofUpdated', 'num_events': 1, 'event_args': {'closing_participant': 3}}>", "event": "Task errored", "logger": "scenario_player.tasks.base", "level": "error", "timestamp": "2019-09-27 06:06:20.294766", "exception": "Traceback (most recent call last):\n  File \"/usr/local/lib/python3.7/site-packages/scenario_player/tasks/base.py\", line 74, in __call__\n    return self._run(*args, **kwargs)\n  File \"/usr/local/lib/python3.7/site-packages/scenario_player/tasks/blockchain.py\", line 178, in _run\n    f\"Expected number of events ({self.num_events}) did not match the number \"\nscenario_player.exceptions.legacy.ScenarioAssertionError: Expected number of events (1) did not match the number of events found (0)"}
{"task": "<SerialTask: {'name': 'Close channel between 3 and 4 while 4 is offline', 'tasks': [{'stop_node': 4}, {'close_channel': {'from': 3, 'to': 4}}, {'wait_blocks': 1}, {'assert': {'from': 3, 'to': 4, 'state': 'closed'}}, {'assert_events': {'contract_name': 'TokenNetwork', 'event_name': 'ChannelClosed', 'num_events': 1, 'event_args': {'closing_participant': 3}}}, {'wait_blocks': 401}, {'assert_events': {'contract_name': 'TokenNetwork', 'event_name': 'NonClosingBalanceProofUpdated', 'num_events': 1, 'event_args': {'closing_participant': 3}}}, {'wait_blocks': 110}, {'assert_ms_claim': {'channel_info_key': 'MS Test Channel 3-4'}}]}>", "event": "Task errored", "logger": "scenario_player.tasks.base", "level": "error", "timestamp": "2019-09-27 06:06:20.296162", "exception": "Traceback (most recent call last):\n  File \"/usr/local/lib/python3.7/site-packages/scenario_player/tasks/base.py\", line 74, in __call__\n    return self._run(*args, **kwargs)\n  File \"/usr/local/lib/python3.7/site-packages/scenario_player/tasks/execution.py\", line 41, in _run\n    task()\n  File \"/usr/local/lib/python3.7/site-packages/scenario_player/tasks/base.py\", line 74, in __call__\n    return self._run(*args, **kwargs)\n  File \"/usr/local/lib/python3.7/site-packages/scenario_player/tasks/blockchain.py\", line 178, in _run\n    f\"Expected number of events ({self.num_events}) did not match the number \"\nscenario_player.exceptions.legacy.ScenarioAssertionError: Expected number of events (1) did not match the number of events found (0)"}
{"task": "<SerialTask: {'tasks': [{'parallel': {'name': 'Open channels', 'tasks': [{'open_channel': {'from': 0, 'to': 1, 'total_deposit': 1000}}, {'open_channel': {'from': 1, 'to': 2, 'total_deposit': 1000}}, {'open_channel': {'from': 2, 'to': 3, 'total_deposit': 1000}}, {'open_channel': {'from': 0, 'to': 4, 'total_deposit': 1000}}, {'open_channel': {'from': 4, 'to': 3, 'total_deposit': 1000}}]}}, {'parallel': {'name': 'Assert after channel openings', 'tasks': [{'assert': {'from': 0, 'to': 1, 'total_deposit': 1000, 'balance': 1000, 'state': 'opened'}}, {'assert': {'from': 1, 'to': 2, 'total_deposit': 1000, 'balance': 1000, 'state': 'opened'}}, {'assert': {'from': 2, 'to': 3, 'total_deposit': 1000, 'balance': 1000, 'state': 'opened'}}, {'assert': {'from': 0, 'to': 4, 'total_deposit': 1000, 'balance': 1000, 'state': 'opened'}}, {'assert': {'from': 4, 'to': 3, 'total_deposit': 1000, 'balance': 1000, 'state': 'opened'}}]}}, {'serial': {'name': 'Make transfer in the direction with no deposit (should fail)', 'tasks': [{'transfer': {'from': 3, 'to': 0, 'amount': 10, 'expected_http_status': 409}}]}}, {'parallel': {'name': 'Deposit in the other directions', 'tasks': [{'deposit': {'from': 1, 'to': 0, 'total_deposit': 1000}}, {'deposit': {'from': 2, 'to': 1, 'total_deposit': 1000}}, {'deposit': {'from': 3, 'to': 2, 'total_deposit': 1000}}, {'deposit': {'from': 3, 'to': 4, 'total_deposit': 1000}}, {'deposit': {'from': 4, 'to': 0, 'total_deposit': 1000}}]}}, {'parallel': {'name': 'Assert after deposits', 'tasks': [{'assert': {'from': 1, 'to': 0, 'total_deposit': 1000, 'balance': 1000, 'state': 'opened'}}, {'assert': {'from': 2, 'to': 1, 'total_deposit': 1000, 'balance': 1000, 'state': 'opened'}}, {'assert': {'from': 3, 'to': 2, 'total_deposit': 1000, 'balance': 1000, 'state': 'opened'}}, {'assert': {'from': 4, 'to': 0, 'total_deposit': 1000, 'balance': 1000, 'state': 'opened'}}, {'assert': {'from': 3, 'to': 4, 'total_deposit': 1000, 'balance': 1000, 'state': 'opened'}}]}}, {'parallel': {'name': 'Enable MSs between node 4 and 3 (will be used later in the scenario)', 'tasks': [{'store_channel_info': {'from': 4, 'to': 3, 'key': 'MS Test Channel 3-4'}}]}}, {'serial': {'name': 'Make 10 transfers from 3 to 0', 'repeat': 10, 'tasks': [{'transfer': {'from': 3, 'to': 0, 'amount': 1}}]}}, {'serial': {'name': 'Assert after 10 payments from 3 to 0', 'tasks': [{'wait': 10}, {'assert_sum': {'from': 0, 'balance_sum': 2010}}, {'assert_sum': {'from': 3, 'balance_sum': 1990}}]}}, {'serial': {'name': 'Make 10 transfers from 1 to 4', 'repeat': 10, 'tasks': [{'transfer': {'from': 1, 'to': 4, 'amount': 1}}]}}, {'serial': {'name': 'Assert after 10 payments from 1 to 4', 'tasks': [{'wait': 10}, {'assert_sum': {'from': 1, 'balance_sum': 1990}}, {'assert_sum': {'from': 4, 'balance_sum': 2010}}]}}, {'serial': {'name': 'Check that IOUs exist after the payments', 'tasks': [{'wait': 10}, {'assert_pfs_history': {'source': 3, 'target': 0, 'request_count': 11}}, {'assert_pfs_iou': {'source': 3, 'amount': 1100}}, {'assert_pfs_history': {'source': 1, 'target': 4, 'request_count': 10}}, {'assert_pfs_iou': {'source': 1, 'amount': 1000}}, {'assert_pfs_iou': {'source': 2, 'iou_exists': False}}]}}, {'serial': {'name': 'Withdraw 10% of the deposit of node 2', 'tasks': [{'withdraw': {'from': 2, 'to': 3, 'total_withdraw': 100, 'expected_http_status': 200}}]}}, {'parallel': {'name': 'Assert after withdraw', 'tasks': [{'assert': {'from': 2, 'to': 3, 'total_deposit': 1000, 'total_withdraw': 100, 'state': 'opened'}}]}}, {'serial': {'name': 'Make payments from 2 to 4 after withdraw', 'repeat': 10, 'tasks': [{'transfer': {'from': 2, 'to': 4, 'amount': 1}}]}}, {'serial': {'name': 'Assert after 10 payments from 2 to 4', 'tasks': [{'wait': 10}, {'assert_sum': {'from': 2, 'balance_sum': 1890}}, {'assert_sum': {'from': 4, 'balance_sum': 2020}}]}}, {'serial': {'name': 'Make payments from 0 to 2 after withdraw', 'repeat': 5, 'tasks': [{'transfer': {'from': 0, 'to': 2, 'amount': 1}}]}}, {'serial': {'name': 'Assert after 5 payments from 0 to 2', 'tasks': [{'wait': 10}, {'assert_sum': {'from': 2, 'balance_sum': 1895}}, {'assert_sum': {'from': 0, 'balance_sum': 2005}}]}}, {'parallel': {'name': '2 deposits back the 10% it withdrew', 'tasks': [{'deposit': {'from': 2, 'to': 3, 'total_deposit': 1100}}]}}, {'serial': {'name': 'Assert after deposit from 2 to 3', 'tasks': [{'wait': 10}, {'assert': {'from': 2, 'to': 3, 'total_deposit': 1100, 'total_withdraw': 100, 'state': 'opened'}}]}}, {'parallel': {'name': '1 deposits extra 10% in the channel with 0', 'tasks': [{'deposit': {'from': 1, 'to': 0, 'total_deposit': 1100}}]}}, {'serial': {'name': 'Assert after deposit from 1 to 0', 'tasks': [{'wait': 10}, {'assert': {'from': 1, 'to': 0, 'total_deposit': 1100, 'state': 'opened'}}]}}, {'serial': {'name': 'Make 100 payments from 0 to 3', 'repeat': 100, 'tasks': [{'transfer': {'from': 0, 'to': 3, 'amount': 1}}]}}, {'serial': {'name': 'Assert after 100 payments from 0 to 3', 'tasks': [{'wait': 10}, {'assert_sum': {'from': 0, 'balance_sum': 1905}}, {'assert_sum': {'from': 3, 'balance_sum': 2090}}]}}, {'serial': {'name': 'Stop node 0 and wait 10 blocks, then start it again', 'tasks': [{'stop_node': 0}, {'wait_blocks': 10}, {'start_node': 0}]}}, {'serial': {'name': 'Make 10 payments from 0 to 3 after restart', 'repeat': 10, 'tasks': [{'transfer': {'from': 0, 'to': 3, 'amount': 1}}]}}, {'serial': {'name': 'Assert after 10 payments from 0 to 3', 'tasks': [{'wait': 10}, {'assert_sum': {'from': 0, 'balance_sum': 1895}}, {'assert_sum': {'from': 3, 'balance_sum': 2100}}]}}, {'serial': {'name': 'Close channel between 0 and 4', 'tasks': [{'close_channel': {'from': 0, 'to': 4}}]}}, {'serial': {'name': 'Assert after closing channel between 0 and 4', 'tasks': [{'wait': 10}, {'assert_events': {'contract_name': 'TokenNetwork', 'event_name': 'ChannelClosed', 'num_events': 1, 'event_args': {'closing_participant': 0}}}, {'assert': {'from': 0, 'to': 4, 'state': 'closed'}}]}}, {'serial': {'name': 'Make 100 payments from 3 to 0', 'repeat': 100, 'tasks': [{'transfer': {'from': 3, 'to': 0, 'amount': 1}}]}}, {'serial': {'name': 'Assert after 100 payments from 3 to 0', 'tasks': [{'wait': 10}, {'assert_sum': {'from': 0, 'balance_sum': 1995}}, {'assert_sum': {'from': 3, 'balance_sum': 2000}}]}}, {'serial': {'name': 'Close channel between 3 and 4 while 4 is offline', 'tasks': [{'stop_node': 4}, {'close_channel': {'from': 3, 'to': 4}}, {'wait_blocks': 1}, {'assert': {'from': 3, 'to': 4, 'state': 'closed'}}, {'assert_events': {'contract_name': 'TokenNetwork', 'event_name': 'ChannelClosed', 'num_events': 1, 'event_args': {'closing_participant': 3}}}, {'wait_blocks': 401}, {'assert_events': {'contract_name': 'TokenNetwork', 'event_name': 'NonClosingBalanceProofUpdated', 'num_events': 1, 'event_args': {'closing_participant': 3}}}, {'wait_blocks': 110}, {'assert_ms_claim': {'channel_info_key': 'MS Test Channel 3-4'}}]}}]}>", "event": "Task errored", "logger": "scenario_player.tasks.base", "level": "error", "timestamp": "2019-09-27 06:06:20.297271", "exception": "Traceback (most recent call last):\n  File \"/usr/local/lib/python3.7/site-packages/scenario_player/tasks/base.py\", line 74, in __call__\n    return self._run(*args, **kwargs)\n  File \"/usr/local/lib/python3.7/site-packages/scenario_player/tasks/execution.py\", line 41, in _run\n    task()\n  File \"/usr/local/lib/python3.7/site-packages/scenario_player/tasks/base.py\", line 74, in __call__\n    return self._run(*args, **kwargs)\n  File \"/usr/local/lib/python3.7/site-packages/scenario_player/tasks/execution.py\", line 41, in _run\n    task()\n  File \"/usr/local/lib/python3.7/site-packages/scenario_player/tasks/base.py\", line 74, in __call__\n    return self._run(*args, **kwargs)\n  File \"/usr/local/lib/python3.7/site-packages/scenario_player/tasks/blockchain.py\", line 178, in _run\n    f\"Expected number of events ({self.num_events}) did not match the number \"\nscenario_player.exceptions.legacy.ScenarioAssertionError: Expected number of events (1) did not match the number of events found (0)"}
{"result": "assertion errors", "event": "Run finished", "logger": "scenario_player.main", "level": "error", "timestamp": "2019-09-27 06:06:20.301653"}

and the exception in a more readable format:

Traceback (most recent call last):
  File \"/usr/local/lib/python3.7/site-packages/scenario_player/tasks/base.py\", line 74, in __call__
    return self._run(*args, **kwargs)
  File \"/usr/local/lib/python3.7/site-packages/scenario_player/tasks/execution.py\", line 41, in _run
    task()
  File \"/usr/local/lib/python3.7/site-packages/scenario_player/tasks/base.py\", line 74, in __call__
    return self._run(*args, **kwargs)
  File \"/usr/local/lib/python3.7/site-packages/scenario_player/tasks/execution.py\", line 41, in _run
    task()
  File \"/usr/local/lib/python3.7/site-packages/scenario_player/tasks/base.py\", line 74, in __call__
    return self._run(*args, **kwargs)
  File \"/usr/local/lib/python3.7/site-packages/scenario_player/tasks/blockchain.py\", line 178, in _run
    f\"Expected number of events ({self.num_events}) did not match the number \"
scenario_player.exceptions.legacy.ScenarioAssertionError: Expected number of events (1) did not match the number of events found (0)"

which is the same as the MS1/MS2 scenarios (seen here) concerning the lack of NonClosingBalanceProofUpdated event after the 401 blocks wait.

raiden-network / raiden

BF1 scenario failed #4990

Issue checklist