search

raiden-network / raiden

Raiden Network
https://developer.raiden.network
Other
1.84k stars 378 forks source link

BF1 AssertPFSHistoryTask Fail Expected request_count 10 but got 19 #5684

Closed agatsoh closed 4 years ago

agatsoh commented 4 years ago

Problem Definition

BF1 Scenario log gives

{
  "task": "<AssertPFSHistoryTask: {'source': 3, 'target': 0, 'request_count': 10}>",
  "event": "Task errored",
  "logger": "scenario_player.tasks.base",
  "level": "error",
  "timestamp": "2020-01-16 22:34:08.027936",
  "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/api_base.py\", line 70, in _run\n    return self._process_response(response_dict)\n  File \"/usr/local/lib/python3.7/site-packages/scenario_player/tasks/services.py\", line 216, in _process_response\n    f\"Expected request_count {exp_request_count} but got {actual_request_count}\"\nscenario_player.exceptions.legacy.ScenarioAssertionError: Expected request_count 10 but got 19"
}

Information from the exception

  1. Expected request_count 10 but got 19

  2. Fails AssertPFSHistoryTask at line 126

- assert_pfs_history: {source: 3, target: 0, request_count: 10}

Logs: http://139.59.211.171:8000/scenario-player/scenarios/bf1_basic_functionality/ node logs node_52_xxx

Dominik1999 commented 4 years ago

So it looks like, Node 3 is sending 10 Requests and IOUs to the pfs and receives 10 routes. But the PFS only returns 7 routes.

Node 3 seems to have requested 10 times

command to extract logs:

cat run-052-node3.log | grep -i "Requesting paths from Pathfinding Service" | jq -s '.[] | select(.event == "Requesting paths from Pathfinding Service") | {"timestamp": .timestamp, "url": .url, "sender": .payload.iou.sender, "amount": .payload.iou.amount}'

result:

{
  "timestamp": "2020-01-16 22:23:56.852265",
  "url": "https://pfs-goerli-with-fee.services-dev.raiden.network",
  "sender": "0xc702069D3B1DDe01264F58cEe9689164497e5305",
  "amount": 100
}
{
  "timestamp": "2020-01-16 22:24:33.173708",
  "url": "https://pfs-goerli-with-fee.services-dev.raiden.network",
  "sender": "0xc702069D3B1DDe01264F58cEe9689164497e5305",
  "amount": 200
}
{
  "timestamp": "2020-01-16 22:24:53.377045",
  "url": "https://pfs-goerli-with-fee.services-dev.raiden.network",
  "sender": "0xc702069D3B1DDe01264F58cEe9689164497e5305",
  "amount": 300
}
{
  "timestamp": "2020-01-16 22:25:17.136684",
  "url": "https://pfs-goerli-with-fee.services-dev.raiden.network",
  "sender": "0xc702069D3B1DDe01264F58cEe9689164497e5305",
  "amount": 400
}
{
  "timestamp": "2020-01-16 22:25:33.693525",
  "url": "https://pfs-goerli-with-fee.services-dev.raiden.network",
  "sender": "0xc702069D3B1DDe01264F58cEe9689164497e5305",
  "amount": 500
}
{
  "timestamp": "2020-01-16 22:25:54.210151",
  "url": "https://pfs-goerli-with-fee.services-dev.raiden.network",
  "sender": "0xc702069D3B1DDe01264F58cEe9689164497e5305",
  "amount": 600
}
{
  "timestamp": "2020-01-16 22:26:15.456071",
  "url": "https://pfs-goerli-with-fee.services-dev.raiden.network",
  "sender": "0xc702069D3B1DDe01264F58cEe9689164497e5305",
  "amount": 700
}
{
  "timestamp": "2020-01-16 22:26:34.178794",
  "url": "https://pfs-goerli-with-fee.services-dev.raiden.network",
  "sender": "0xc702069D3B1DDe01264F58cEe9689164497e5305",
  "amount": 800
}
{
  "timestamp": "2020-01-16 22:26:59.364853",
  "url": "https://pfs-goerli-with-fee.services-dev.raiden.network",
  "sender": "0xc702069D3B1DDe01264F58cEe9689164497e5305",
  "amount": 900
}
{
  "timestamp": "2020-01-16 22:27:22.432694",
  "url": "https://pfs-goerli-with-fee.services-dev.raiden.network",
  "sender": "0xc702069D3B1DDe01264F58cEe9689164497e5305",
  "amount": 1000
}

and the node got 10 routes back 

{
  "timestamp": "2020-01-16 22:23:57.108130",
  "routes": [
    "RouteState (0xc702069D3B1DDe01264F58cEe9689164497e5305 -> 0xFd736984f03007EF4d7473C01a15b779a0903067 -> 0x2c0270A01C47eB5ff739Befc8086BC6d33651612), channel_id: 8553, fee: 0"
  ]
}
{
  "timestamp": "2020-01-16 22:24:33.467845",
  "routes": [
    "RouteState (0xc702069D3B1DDe01264F58cEe9689164497e5305 -> 0xFd736984f03007EF4d7473C01a15b779a0903067 -> 0x2c0270A01C47eB5ff739Befc8086BC6d33651612), channel_id: 8553, fee: 0",
    "RouteState (0xc702069D3B1DDe01264F58cEe9689164497e5305 -> 0xcbE11643F9853ccE3b7e35152813e2E4CA5ec4C1 -> 0xa7425Aa9a0596FA6501756E1bbA4BF98aF4b4E02 -> 0x2c0270A01C47eB5ff739Befc8086BC6d33651612), channel_id: 8555, fee: 0"
  ]
}
{
  "timestamp": "2020-01-16 22:24:53.788196",
  "routes": [
    "RouteState (0xc702069D3B1DDe01264F58cEe9689164497e5305 -> 0xFd736984f03007EF4d7473C01a15b779a0903067 -> 0x2c0270A01C47eB5ff739Befc8086BC6d33651612), channel_id: 8553, fee: 0",
    "RouteState (0xc702069D3B1DDe01264F58cEe9689164497e5305 -> 0xcbE11643F9853ccE3b7e35152813e2E4CA5ec4C1 -> 0xa7425Aa9a0596FA6501756E1bbA4BF98aF4b4E02 -> 0x2c0270A01C47eB5ff739Befc8086BC6d33651612), channel_id: 8555, fee: 0"
  ]
}
{
  "timestamp": "2020-01-16 22:25:17.453183",
  "routes": [
    "RouteState (0xc702069D3B1DDe01264F58cEe9689164497e5305 -> 0xFd736984f03007EF4d7473C01a15b779a0903067 -> 0x2c0270A01C47eB5ff739Befc8086BC6d33651612), channel_id: 8553, fee: 0",
    "RouteState (0xc702069D3B1DDe01264F58cEe9689164497e5305 -> 0xcbE11643F9853ccE3b7e35152813e2E4CA5ec4C1 -> 0xa7425Aa9a0596FA6501756E1bbA4BF98aF4b4E02 -> 0x2c0270A01C47eB5ff739Befc8086BC6d33651612), channel_id: 8555, fee: 0"
  ]
}
{
  "timestamp": "2020-01-16 22:25:33.937648",
  "routes": [
    "RouteState (0xc702069D3B1DDe01264F58cEe9689164497e5305 -> 0xFd736984f03007EF4d7473C01a15b779a0903067 -> 0x2c0270A01C47eB5ff739Befc8086BC6d33651612), channel_id: 8553, fee: 0",
    "RouteState (0xc702069D3B1DDe01264F58cEe9689164497e5305 -> 0xcbE11643F9853ccE3b7e35152813e2E4CA5ec4C1 -> 0xa7425Aa9a0596FA6501756E1bbA4BF98aF4b4E02 -> 0x2c0270A01C47eB5ff739Befc8086BC6d33651612), channel_id: 8555, fee: 0"
  ]
}
{
  "timestamp": "2020-01-16 22:25:54.605335",
  "routes": [
    "RouteState (0xc702069D3B1DDe01264F58cEe9689164497e5305 -> 0xFd736984f03007EF4d7473C01a15b779a0903067 -> 0x2c0270A01C47eB5ff739Befc8086BC6d33651612), channel_id: 8553, fee: 0",
    "RouteState (0xc702069D3B1DDe01264F58cEe9689164497e5305 -> 0xcbE11643F9853ccE3b7e35152813e2E4CA5ec4C1 -> 0xa7425Aa9a0596FA6501756E1bbA4BF98aF4b4E02 -> 0x2c0270A01C47eB5ff739Befc8086BC6d33651612), channel_id: 8555, fee: 0"
  ]
}
{
  "timestamp": "2020-01-16 22:26:15.728544",
  "routes": [
    "RouteState (0xc702069D3B1DDe01264F58cEe9689164497e5305 -> 0xFd736984f03007EF4d7473C01a15b779a0903067 -> 0x2c0270A01C47eB5ff739Befc8086BC6d33651612), channel_id: 8553, fee: 0",
    "RouteState (0xc702069D3B1DDe01264F58cEe9689164497e5305 -> 0xcbE11643F9853ccE3b7e35152813e2E4CA5ec4C1 -> 0xa7425Aa9a0596FA6501756E1bbA4BF98aF4b4E02 -> 0x2c0270A01C47eB5ff739Befc8086BC6d33651612), channel_id: 8555, fee: 0"
  ]
}
{
  "timestamp": "2020-01-16 22:26:34.428887",
  "routes": [
    "RouteState (0xc702069D3B1DDe01264F58cEe9689164497e5305 -> 0xFd736984f03007EF4d7473C01a15b779a0903067 -> 0x2c0270A01C47eB5ff739Befc8086BC6d33651612), channel_id: 8553, fee: 0",
    "RouteState (0xc702069D3B1DDe01264F58cEe9689164497e5305 -> 0xcbE11643F9853ccE3b7e35152813e2E4CA5ec4C1 -> 0xa7425Aa9a0596FA6501756E1bbA4BF98aF4b4E02 -> 0x2c0270A01C47eB5ff739Befc8086BC6d33651612), channel_id: 8555, fee: 0"
  ]
}
{
  "timestamp": "2020-01-16 22:26:59.633455",
  "routes": [
    "RouteState (0xc702069D3B1DDe01264F58cEe9689164497e5305 -> 0xFd736984f03007EF4d7473C01a15b779a0903067 -> 0x2c0270A01C47eB5ff739Befc8086BC6d33651612), channel_id: 8553, fee: 0",
    "RouteState (0xc702069D3B1DDe01264F58cEe9689164497e5305 -> 0xcbE11643F9853ccE3b7e35152813e2E4CA5ec4C1 -> 0xa7425Aa9a0596FA6501756E1bbA4BF98aF4b4E02 -> 0x2c0270A01C47eB5ff739Befc8086BC6d33651612), channel_id: 8555, fee: 0"
  ]
}
{
  "timestamp": "2020-01-16 22:27:22.674503",
  "routes": [
    "RouteState (0xc702069D3B1DDe01264F58cEe9689164497e5305 -> 0xFd736984f03007EF4d7473C01a15b779a0903067 -> 0x2c0270A01C47eB5ff739Befc8086BC6d33651612), channel_id: 8553, fee: 0",
    "RouteState (0xc702069D3B1DDe01264F58cEe9689164497e5305 -> 0xcbE11643F9853ccE3b7e35152813e2E4CA5ec4C1 -> 0xa7425Aa9a0596FA6501756E1bbA4BF98aF4b4E02 -> 0x2c0270A01C47eB5ff739Befc8086BC6d33651612), channel_id: 8555, fee: 0"
  ]
}

But the pfs only returns 7 routes:

cat pfs.log | grep -P '0xc702069D3B1DDe01264F58cEe9689164497e5305.*Returning paths for payment'

pfs-goerli-with-fee_1         | {"source": "0xc702069D3B1DDe01264F58cEe9689164497e5305", "target": "0x2c0270A01C47eB5ff739Befc8086BC6d33651612", "value": 1000000000000000, "max_paths": 5, "diversity_penalty": 5, "fee_penalty": 100, "paths": ["<pathfinding_service.model.token_network.Path object at 0x7fa5d3254a90>"], "event": "Returning paths for payment", "level": "info", "logger": "pathfinding_service.model.token_network", "timestamp": "2020-01-16 22:23:57.091560"}
pfs-goerli-with-fee_1         | {"source": "0xc702069D3B1DDe01264F58cEe9689164497e5305", "target": "0x2c0270A01C47eB5ff739Befc8086BC6d33651612", "value": 1000000000000000, "max_paths": 5, "diversity_penalty": 5, "fee_penalty": 100, "paths": ["<pathfinding_service.model.token_network.Path object at 0x7fa5d3375f10>", "<pathfinding_service.model.token_network.Path object at 0x7fa5d40e39d0>"], "event": "Returning paths for payment", "level": "info", "logger": "pathfinding_service.model.token_network", "timestamp": "2020-01-16 22:24:33.458049"}
pfs-goerli-with-fee_1         | {"source": "0xc702069D3B1DDe01264F58cEe9689164497e5305", "target": "0x2c0270A01C47eB5ff739Befc8086BC6d33651612", "value": 1000000000000000, "max_paths": 5, "diversity_penalty": 5, "fee_penalty": 100, "paths": ["<pathfinding_service.model.token_network.Path object at 0x7fa5d54d7250>", "<pathfinding_service.model.token_network.Path object at 0x7fa5d3330d90>"], "event": "Returning paths for payment", "level": "info", "logger": "pathfinding_service.model.token_network", "timestamp": "2020-01-16 22:24:53.775499"}
pfs-goerli-with-fee_1         | {"source": "0xc702069D3B1DDe01264F58cEe9689164497e5305", "target": "0x2c0270A01C47eB5ff739Befc8086BC6d33651612", "value": 1000000000000000, "max_paths": 5, "diversity_penalty": 5, "fee_penalty": 100, "paths": ["<pathfinding_service.model.token_network.Path object at 0x7fa5d3305610>", "<pathfinding_service.model.token_network.Path object at 0x7fa5d1c7d050>"], "event": "Returning paths for payment", "level": "info", "logger": "pathfinding_service.model.token_network", "timestamp": "2020-01-16 22:25:33.930180"}
pfs-goerli-with-fee_1         | {"source": "0xc702069D3B1DDe01264F58cEe9689164497e5305", "target": "0x2c0270A01C47eB5ff739Befc8086BC6d33651612", "value": 1000000000000000, "max_paths": 5, "diversity_penalty": 5, "fee_penalty": 100, "paths": ["<pathfinding_service.model.token_network.Path object at 0x7fa5d237d090>", "<pathfinding_service.model.token_network.Path object at 0x7fa5d54d7650>"], "event": "Returning paths for payment", "level": "info", "logger": "pathfinding_service.model.token_network", "timestamp": "2020-01-16 22:25:54.594357"}
pfs-goerli-with-fee_1         | {"source": "0xc702069D3B1DDe01264F58cEe9689164497e5305", "target": "0x2c0270A01C47eB5ff739Befc8086BC6d33651612", "value": 1000000000000000, "max_paths": 5, "diversity_penalty": 5, "fee_penalty": 100, "paths": ["<pathfinding_service.model.token_network.Path object at 0x7fa5d26f6310>", "<pathfinding_service.model.token_network.Path object at 0x7fa5d26f6550>"], "event": "Returning paths for payment", "level": "info", "logger": "pathfinding_service.model.token_network", "timestamp": "2020-01-16 22:26:34.422190"}
pfs-goerli-with-fee_1         | {"source": "0xc702069D3B1DDe01264F58cEe9689164497e5305", "target": "0x2c0270A01C47eB5ff739Befc8086BC6d33651612", "value": 1000000000000000, "max_paths": 5, "diversity_penalty": 5, "fee_penalty": 100, "paths": ["<pathfinding_service.model.token_network.Path object at 0x7fa5d3265450>", "<pathfinding_service.model.token_network.Path object at 0x7fa5d26ffc50>"], "event": "Returning paths for payment", "level": "info", "logger": "pathfinding_service.model.token_network", "timestamp": "2020-01-16 22:26:59.626987"}

and the pfs only received 7 IOUs

cat pfs.log | grep -P '0xc702069D3B1DDe01264F58cEe9689164497e5305.*Received service fee'                                                               

pfs-goerli-with-fee_1         | {"sender": "0xc702069D3B1DDe01264F58cEe9689164497e5305", "expected_amount": 100, "total_amount": 100, "added_amount": 0, "event": "Received service fee", "level": "info", "logger": "pathfinding_service.api", "timestamp": "2020-01-16 22:23:57.028327"}
pfs-goerli-with-fee_1         | {"sender": "0xc702069D3B1DDe01264F58cEe9689164497e5305", "expected_amount": 200, "total_amount": 200, "added_amount": 100, "event": "Received service fee", "level": "info", "logger": "pathfinding_service.api", "timestamp": "2020-01-16 22:24:33.325762"}
pfs-goerli-with-fee_1         | {"sender": "0xc702069D3B1DDe01264F58cEe9689164497e5305", "expected_amount": 300, "total_amount": 300, "added_amount": 200, "event": "Received service fee", "level": "info", "logger": "pathfinding_service.api", "timestamp": "2020-01-16 22:24:53.661384"}
pfs-goerli-with-fee_1         | {"sender": "0xc702069D3B1DDe01264F58cEe9689164497e5305", "expected_amount": 500, "total_amount": 500, "added_amount": 400, "event": "Received service fee", "level": "info", "logger": "pathfinding_service.api", "timestamp": "2020-01-16 22:25:33.839912"}
pfs-goerli-with-fee_1         | {"sender": "0xc702069D3B1DDe01264F58cEe9689164497e5305", "expected_amount": 600, "total_amount": 600, "added_amount": 500, "event": "Received service fee", "level": "info", "logger": "pathfinding_service.api", "timestamp": "2020-01-16 22:25:54.506284"}
pfs-goerli-with-fee_1         | {"sender": "0xc702069D3B1DDe01264F58cEe9689164497e5305", "expected_amount": 800, "total_amount": 800, "added_amount": 700, "event": "Received service fee", "level": "info", "logger": "pathfinding_service.api", "timestamp": "2020-01-16 22:26:34.307538"}
pfs-goerli-with-fee_1         | {"sender": "0xc702069D3B1DDe01264F58cEe9689164497e5305", "expected_amount": 900, "total_amount": 900, "added_amount": 800, "event": "Received service fee", "level": "info", "logger": "pathfinding_service.api", "timestamp": "2020-01-16 22:26:59.543177"}
Dominik1999 commented 4 years ago

@palango here are the logs

200116-bf1-lost-iou-fail.zip 200116-bf1-lost-iou-fail-2.zip 200116-bf1-lost-iou-fail-3.zip

agatsoh commented 4 years ago

Same exception occurs in bf1 again on 21st Jan 2020

{
  "task": "<AssertPFSHistoryTask: {'source': 3, 'target': 0, 'request_count': 10}>",
  "event": "Task errored",
  "logger": "scenario_player.tasks.base",
  "level": "error",
  "timestamp": "2020-01-20 22:36:44.141650",
  "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/api_base.py\", line 70, in _run\n    return self._process_response(response_dict)\n  File \"/usr/local/lib/python3.7/site-packages/scenario_player/tasks/services.py\", line 216, in _process_response\n    f\"Expected request_count {exp_request_count} but got {actual_request_count}\"\nscenario_player.exceptions.legacy.ScenarioAssertionError: Expected request_count 10 but got 20"
}

Expected request_count 10 but got 20

http://139.59.211.171:8000/scenario-player/scenarios/bf1_basic_functionality/

node logs at http://139.59.211.171:8000/scenario-player/scenarios/bf1_basic_functionality/node_58_000/

Dominik1999 commented 4 years ago

Should be fixed by https://github.com/raiden-network/raiden-services/pull/708