search

raiden-network / raiden

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

mfee 4 fail, Payment couldn't be completed because: bad secret request message from target #5101

Closed agatsoh closed 4 years ago

agatsoh commented 4 years ago

Problem Definition

The mfee4 scenario fails due to error Payment couldn't be completed because: bad secret request message from target

{"task": "<TransferTask: {'from': 0, 'to': 3, 'amount': 500000000000000000, 'expected_http_status': 200}>", "event": "Task errored", "logger": "scenario_player.tasks.base", "level": "error", "timestamp": "2019-10-16 06:17:16.341146", "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 59, in _run\n f'HTTP status code \"{resp.status_code}\" while fetching {url}. '\nscenario_player.exceptions.legacy.RESTAPIStatusMismatchError: HTTP status code \"409\" while fetching http://127.0.0.1:50225/api/v1/payments/0x62083c80353Df771426D209eF578619EE68D5C7A/0x6bEacCD54d1C951b9E0100A6f6906F791E923675. Expected 200: {\"errors\": \"Payment couldn't be completed because: bad secret request message from target\"}"} Scenario_player_Logs-mfee4_combined_fees-1-latest-2019-10-16.tar.gz

Dominik1999 commented 4 years ago

Can you please provide us with the logs, we cannot debug without that information

agatsoh commented 4 years ago

Just updated the Intial comment with the logs

Dominik1999 commented 4 years ago

Can you please provide the logs of that fail together with logs of the nodes of that fail.

The logs of the nodes are from the 26th September as you can see in the timestamp.

{"raiden": "0.100.5a1.dev445+gf40adc88e", "raiden_db_version": 23, "python_implementation": "CPython", "python_version": "3.7.3", "system": "Linux 64bit 4.15.0-62-generic", "architecture": "x86_64", "distribution": "source", "event": "Starting Raiden", "logger": "raiden.ui.runners", "level": "info", "timestamp": "2019-09-26 07:07:32.298556"}{"raiden": "0.100.5a1.dev445+gf40adc88e", "raiden_db_version": 23, "python_implementation": "CPython", "python_version": "3.7.3", "system": "Linux 64bit 4.15.0-62-generic", "architecture": "x86_64", "distribution": "source", "event": "Starting Raiden", "logger": "raiden.ui.runners", "level": "info", "timestamp": "2019-09-26 07:07:32.298556"}
agatsoh commented 4 years ago

@Dominik1999. There is a serious issue with the scenario player I just uploaded the logs as I got them from the monitoring channel. I just checked the scenario logs but not the node logs. Sorry about that. This means that the SP is using the raiden packaged on the 26th of September.

As a sample I ran the bf1 scenario on my local machine and the run-000.log file from my local machine shows something like this

{"raiden": "0.100.5a1.dev559+g9c93684c9.d20191015", "raiden_db_version": 23, "python_implementation": "CPython", "python_version": "3.7.4", "system": "Linux 64bit 5.0.0-23-generic", "architecture": "x86_64", "distribution": "source", "event": "Starting Raiden", "logger": "raiden.ui.runners", "level": "info", "timestamp": "2019-10-15 19:58:12.807846"}

christianbrb commented 4 years ago

According to @Dominik1999 the logs are not needed any more

Dominik1999 commented 4 years ago

node_24_00.zip

karlb commented 4 years ago

EDIT: This is wrong. See below.

From the logs, the payment is actually successful:

    {
      "secret": "<redacted>",
      "identifier": "13954325238838821177",
      "amount": "10000",
      "route": [
        "0xAf763164E8950d439435D0188518bb5a6e35B49D",
        "0x225937089eC07a997f5C11832Cc4f0bc2204d891",
        "0x198CCfE32ADe0ac87f35B6C209530a255270963E",
        "0x5C0f1d3d22CaF5A77Ff449ec752c1BD985f14E43"
      ],
      "token_network_address": "0x483b937b035a70526a9e8E60a2dDdfcFB5fe3B11",
      "target": "0x5C0f1d3d22CaF5A77Ff449ec752c1BD985f14E43",
      "token_network_registry_address": "0x603882F4e7fAb5942a585048CADc71F91D6160c5",
      "_type": "raiden.transfer.events.EventPaymentSentSuccess"
    },

but for some reason it still runs into

def handle_block(...)
    ...
    if lock_has_expired and initiator_state.transfer_state != "transfer_expired":
        ...
        if initiator_state.received_secret_request:
            reason = "bad secret request message from target"
Dominik1999 commented 4 years ago

Can someone potentially lose money due to this bug? When a successful payment is not recognized as being successful it might be tried again by the initiator.

karlb commented 4 years ago

Since @agatsoh's has wrong logs due to a log server bug and @Dominik1999 packed run 24 instead of 25, I was looking at the wrong data. Disregard my comment above.

karlb commented 4 years ago

The Initiator does not reveal the secret because the following requirement is violated:

state_change.amount >= initiator_state.transfer_description.amount
464333139088843162 >= 500000000000000000

This happened because the Initiator only sent 500000000000000000 but the mediators took mediation fees, not leaving enough tokens for the target. This is related to the mediation fee capping which did not work as intended between https://github.com/raiden-network/raiden/pull/5054 and https://github.com/raiden-network/raiden/pull/5089.

It should work fine with the current scenario+PFS+Raiden, but I can't verify it at the moment due to the other known problems.