Scenario bf1 failed with RequestCount assertion

[LefterisJP]

As seen here.

The scenario failed here: https://github.com/raiden-network/raiden/blob/e34025fd39504da04697cc3a84f76b0b3086d0d1/raiden/tests/scenarios/bf1_basic_functionality.yaml#L126

with

scenario_player.exceptions.legacy.ScenarioAssertionError: Expected request_count 11 but got 10

Logs and DB for the scenario run are here

[palango]

The PFS logs are gone for this issue, so we need to reproduce it to find out more.

[palango]

In a recent run I saw a similar problem.

The cause was that the client couldn't connect to the PFS, and fell back to internal routing:

"event": "Request to Pathfinding Service was not successful, falling back to internal routing."

The stacktrace looks like

"Traceback (most recent call last):
  File \"/Users/paul/Projects/brainbot/scenario-player/venv/lib/python3.7/site-packages/urllib3/connection.py\", line 160, in _new_conn
    (self._dns_host, self.port), self.timeout, **extra_kw)
  File \"/Users/paul/Projects/brainbot/scenario-player/venv/lib/python3.7/site-packages/urllib3/util/connection.py\", line 80, in create_connection
    raise err
  File \"/Users/paul/Projects/brainbot/scenario-player/venv/lib/python3.7/site-packages/urllib3/util/connection.py\", line 70, in create_connection
    sock.connect(sa)
  File \"/Users/paul/Projects/brainbot/scenario-player/venv/lib/python3.7/site-packages/gevent/_socket3.py\", line 341, in connect
    self._wait(self._write_event)
  File \"src/gevent/_hub_primitives.py\", line 265, in gevent.__hub_primitives.wait_on_socket
  File \"src/gevent/_hub_primitives.py\", line 266, in gevent.__hub_primitives.wait_on_socket
  File \"src/gevent/_hub_primitives.py\", line 261, in gevent.__hub_primitives._primitive_wait
  File \"src/gevent/_hub_primitives.py\", line 262, in gevent.__hub_primitives._primitive_wait
  File \"src/gevent/_hub_primitives.py\", line 46, in gevent.__hub_primitives.WaitOperationsGreenlet.wait
  File \"src/gevent/_hub_primitives.py\", line 46, in gevent.__hub_primitives.WaitOperationsGreenlet.wait
  File \"src/gevent/_hub_primitives.py\", line 55, in gevent.__hub_primitives.WaitOperationsGreenlet.wait
  File \"src/gevent/_waiter.py\", line 151, in gevent.__waiter.Waiter.get
  File \"src/gevent/_greenlet_primitives.py\", line 59, in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
  File \"src/gevent/_greenlet_primitives.py\", line 59, in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
  File \"src/gevent/_greenlet_primitives.py\", line 63, in gevent.__greenlet_primitives.SwitchOutGreenletWithLoop.switch
  File \"src/gevent/__greenlet_primitives.pxd\", line 35, in gevent.__greenlet_primitives._greenlet_switch
socket.timeout: timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File \"/Users/paul/Projects/brainbot/scenario-player/venv/lib/python3.7/site-packages/urllib3/connectionpool.py\", line 603, in urlopen
    chunked=chunked)
  File \"/Users/paul/Projects/brainbot/scenario-player/venv/lib/python3.7/site-packages/urllib3/connectionpool.py\", line 344, in _make_request
    self._validate_conn(conn)
  File \"/Users/paul/Projects/brainbot/scenario-player/venv/lib/python3.7/site-packages/urllib3/connectionpool.py\", line 843, in _validate_conn
    conn.connect()
  File \"/Users/paul/Projects/brainbot/scenario-player/venv/lib/python3.7/site-packages/urllib3/connection.py\", line 316, in connect
    conn = self._new_conn()
  File \"/Users/paul/Projects/brainbot/scenario-player/venv/lib/python3.7/site-packages/urllib3/connection.py\", line 165, in _new_conn
    (self.host, self.timeout))
urllib3.exceptions.ConnectTimeoutError: (<urllib3.connection.VerifiedHTTPSConnection object at 0x10e90c790>, 'Connection to pfs-goerli-with-fee.services-dev.raiden.network timed out. (connect timeout=1.0)')

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File \"/Users/paul/Projects/brainbot/scenario-player/venv/lib/python3.7/site-packages/requests/adapters.py\", line 449, in send
    timeout=timeout
  File \"/Users/paul/Projects/brainbot/scenario-player/venv/lib/python3.7/site-packages/urllib3/connectionpool.py\", line 641, in urlopen
    _stacktrace=sys.exc_info()[2])
  File \"/Users/paul/Projects/brainbot/scenario-player/venv/lib/python3.7/site-packages/urllib3/util/retry.py\", line 399, in increment
    raise MaxRetryError(_pool, url, error or ResponseError(cause))
urllib3.exceptions.MaxRetryError: HTTPSConnectionPool(host='pfs-goerli-with-fee.services-dev.raiden.network', port=443): Max retries exceeded with url: /api/v1/0xDa1fBc048f503635950058953f5c60FC1F564ee6/paths (Caused by ConnectTimeoutError(<urllib3.connection.VerifiedHTTPSConnection object at 0x10e90c790>, 'Connection to pfs-goerli-with-fee.services-dev.raiden.network timed out. (connect timeout=1.0)'))

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File \"/Users/paul/Projects/brainbot/raiden/raiden/network/pathfinding.py\", line 494, in post_pfs_paths
    timeout=DEFAULT_HTTP_REQUEST_TIMEOUT,
  File \"/Users/paul/Projects/brainbot/scenario-player/venv/lib/python3.7/site-packages/requests/api.py\", line 116, in post
    return request('post', url, data=data, json=json, **kwargs)
  File \"/Users/paul/Projects/brainbot/scenario-player/venv/lib/python3.7/site-packages/requests/api.py\", line 60, in request
    return session.request(method=method, url=url, **kwargs)
  File \"/Users/paul/Projects/brainbot/scenario-player/venv/lib/python3.7/site-packages/requests/sessions.py\", line 533, in request
    resp = self.send(prep, **send_kwargs)
  File \"/Users/paul/Projects/brainbot/scenario-player/venv/lib/python3.7/site-packages/requests/sessions.py\", line 646, in send
    r = adapter.send(request, **kwargs)
  File \"/Users/paul/Projects/brainbot/scenario-player/venv/lib/python3.7/site-packages/requests/adapters.py\", line 504, in send
    raise ConnectTimeout(e, request=request)
requests.exceptions.ConnectTimeout: HTTPSConnectionPool(host='pfs-goerli-with-fee.services-dev.raiden.network', port=443): Max retries exceeded with url: /api/v1/0xDa1fBc048f503635950058953f5c60FC1F564ee6/paths (Caused by ConnectTimeoutError(<urllib3.connection.VerifiedHTTPSConnection object at 0x10e90c790>, 'Connection to pfs-goerli-with-fee.services-dev.raiden.network timed out. (connect timeout=1.0)'))

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File \"/Users/paul/Projects/brainbot/raiden/raiden/routing.py\", line 254, in get_best_routes_pfs
    value=amount,
  File \"/Users/paul/Projects/brainbot/raiden/raiden/network/pathfinding.py\", line 586, in query_paths
    payload=payload,
  File \"/Users/paul/Projects/brainbot/raiden/raiden/network/pathfinding.py\", line 499, in post_pfs_paths
    dict(parameters=payload, exc_info=True),
raiden.exceptions.ServiceRequestFailed: (\"Could not connect to Pathfinding Service (HTTPSConnectionPool(host='pfs-goerli-with-fee.services-dev.raiden.network', port=443): Max retries exceeded with url: /api/v1/0xDa1fBc048f503635950058953f5c60FC1F564ee6/paths (Caused by ConnectTimeoutError(<urllib3.connection.VerifiedHTTPSConnection object at 0x10e90c790>, 'Connection to pfs-goerli-with-fee.services-dev.raiden.network timed out. (connect timeout=1.0)')))\", {'parameters': {'from': '0xA04d084990DEb047D666377D4c6f510cD098e5A4', 'to': '0x72E9338560321BF2EA7dF1dC4e6c902d064122Ab', 'value': 10000, 'max_paths': 5, 'iou': {'sender': '0xA04d084990DEb047D666377D4c6f510cD098e5A4', 'receiver': '0x062C12c01D0f17fC9eAa33940D994594d91a0182', 'one_to_n_address': '0x2aFE254499f20CcCDf043598A17853bE265f2F7a', 'amount': 100, 'expiration_block': 1726139, 'chain_id': 5, 'signature': '0x860fc5b55b32e6d6d123eab46873818c93a4150485d98dc4df8d5c06595935de3d9e5def3de0b747b4c1fefe252b66be5652a9b5284dff95ca4632f9120cdf7a1b'}}, 'exc_info': True})"

[Dominik1999]

closed until we see it in the nightlies to get the logs