Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Slow startup during scenario run #7135

Open
konradkonrad opened this issue Jun 8, 2021 · 5 comments
Open

Slow startup during scenario run #7135

konradkonrad opened this issue Jun 8, 2021 · 5 comments

Comments

@konradkonrad
Copy link
Contributor

konradkonrad commented Jun 8, 2021 •
edited
Loading 

{
  "raiden": "2.0.0rc3",
  "raiden_db_version": 27,
  "python_implementation": "CPython",
  "python_version": "3.7.10",
  "system": "Linux 64bit_ELF 5.12.4-arch1-2",
  "architecture": "x86_64",
  "distribution": "bundled"
}

During scenario run bf1 the node restart is sometimes slow, too slow for the scenario to succeed:

"2021-06-08 08:50:57.956673 Raiden Service stopped"
"2021-06-08 08:51:32.383963 JSONRPCClient created"
"2021-06-08 08:51:32.402520 REST API starting"
"2021-06-08 08:51:32.403309 REST API started"
"2021-06-08 08:51:33.267006 Using Pathfinding Service"
"2021-06-08 08:52:00.413975 Error processing request"

This leads to an error when requesting the task after restart:

2021-06-08 08:52:00.408686 [debug    ] Requesting                     [scenario_player.tasks.api_base] greenlet_name=orchestration json={'amount': 1000000000000000, 'identifier': 149028100231000137, 'lock_timeout': 100} method=post url=http://127.0.0.1:41265/api/v1/payments/0x6B175474E89094C44Da98b954EedeAC495271d0F/0x77F4202069272ddFc3551a98ADD9f9b929B531B5
2021-06-08 08:52:00.415701 [error    ] Task errored                   [scenario_player.tasks.base] greenlet_name=orchestration task=<TransferTask: {'from': 0, 'to': 3, 'amount': 1000000000000000, 'lock_timeout': 100, 'identifier': 149028100231000137}>
Traceback (most recent call last):
  File "/home/konrad/Projects/scenario-player/scenario_player/tasks/base.py", line 140, in __call__
    return_val = self._run(*args, **kwargs)
  File "/home/konrad/Projects/scenario-player/scenario_player/tasks/api_base.py", line 58, in _run
    raise RESTAPIStatusMismatchError(
scenario_player.exceptions.RESTAPIStatusMismatchError: HTTP status code "503" while fetching http://127.0.0.1:41265/api/v1/payments/0x6B175474E89094C44Da98b954EedeAC495271d0F/0x77F4202069272ddFc3551a98ADD9f9b929B531B5. Expected 2..: {"errors": "Service unavailable. Try again later."}
@ulope
Copy link
Collaborator

ulope commented Jun 8, 2021

Can you try manually doing a curl request to both of the PFS' info endpoints from the SP server (ideally from within a docker container)?

I had some slowness when talking to boris' PFS and my current theory is that it's a problem with non-working IPv6.

@konradkonrad
Copy link
Contributor Author

konradkonrad commented Jun 8, 2021 •
edited
Loading

We can see, that there are about 30 seconds from https://github.com/raiden-network/raiden/blob/develop/raiden/ui/app.py#L383 (which ultimately logs Using Pathfinding Service) until the request fails. Within these 30 seconds now further log output is generated.
However, we still see some output in the nodes stdout:

cat /home/konrad/.raiden/scenario-player/scenarios/bf1_basic_functionality/node_0023_000/run-023.stdout 
--------- Starting ---------
Command line: /home/konrad/.local/bin/raiden-v2.0.0rc3-linux-x86_64 --accept-disclaimer --datadir /home/konrad/.raiden/scenario-player/scenarios/bf1_basic_functionality/node_0023_000 --keystore-path /home/konrad/.raiden/scenario-player/scenarios/bf1_basic_functionality/node_0023_000/keys --address 0xA1362e9521E08Ba39cb78b8DCa11Af1C82CD669E --password-file /home/konrad/.raiden/scenario-player/scenarios/bf1_basic_functionality/node_0023_000/password.txt --network-id 1 --sync-check --gas-price fast --eth-rpc-endpoint http://10.104.6.23:8545 --log-config :info,raiden:debug,raiden_contracts:debug,raiden.api.rest.pywsgi:warning --log-json --log-file /home/konrad/.raiden/scenario-player/scenarios/bf1_basic_functionality/node_0023_000/run-023.log --disable-debug-logfile --matrix-server https://transport.raiden.badgateway.tech --api-address 127.0.0.1:41265 --no-web-ui --pathfinding-service-address https://pfs.raiden.overdoze.se --flat-fee 0x6B175474E89094C44Da98b954EedeAC495271d0F 0 --proportional-fee 0x6B175474E89094C44Da98b954EedeAC495271d0F 0 --enable-monitoring --gas-price fast --proportional-imbalance-fee 0x6B175474E89094C44Da98b954EedeAC495271d0F 0 --pathfinding-max-fee 50000000000000000 --routing-mode pfs --environment-type production --default-settle-timeout 100 --default-reveal-timeout 50 --pathfinding-max-paths 5
Welcome to Raiden, version 2.0.0rc3!
[...DISCLAIMER...]
The Raiden API RPC server is now running at http://127.0.0.1:41265/.

See the Raiden documentation for all available endpoints at
https://raiden-network.readthedocs.io/en/latest/rest_api.html
Checking if the ethereum node is synchronized
You have chosen the Pathfinding Service at https://pfs.raiden.overdoze.se.
Operator: hymner, running version: 0.15.4, chain_id: 1.
Fees will be paid to 0x025dCC9F2964C1D7F886f7cB55061115e334bF56. Each request costs 0.045 RDN.
Message from the Pathfinding Service:
Overdoze PFS at your service
Raiden is running in production mode

You are connected to the 'mainnet' network and the DB path is: /home/konrad/.raiden/scenario-player/scenarios/bf1_basic_functionality/node_0023_000/node_a1362e95/netid_1/network_6d07a2ef/v27_log.db
This is the first time Raiden is being used with this address. Processing all the events may take some time. Please wait ...
Synchronization complete, REST API services now available.
--------- Starting ---------
Command line: /home/konrad/.local/bin/raiden-v2.0.0rc3-linux-x86_64 --accept-disclaimer --datadir /home/konrad/.raiden/scenario-player/scenarios/bf1_basic_functionality/node_0023_000 --keystore-path /home/konrad/.raiden/scenario-player/scenarios/bf1_basic_functionality/node_0023_000/keys --address 0xA1362e9521E08Ba39cb78b8DCa11Af1C82CD669E --password-file /home/konrad/.raiden/scenario-player/scenarios/bf1_basic_functionality/node_0023_000/password.txt --network-id 1 --sync-check --gas-price fast --eth-rpc-endpoint http://10.104.6.23:8545 --log-config :info,raiden:debug,raiden_contracts:debug,raiden.api.rest.pywsgi:warning --log-json --log-file /home/konrad/.raiden/scenario-player/scenarios/bf1_basic_functionality/node_0023_000/run-023.log --disable-debug-logfile --matrix-server https://transport.raiden.badgateway.tech --api-address 127.0.0.1:41265 --no-web-ui --pathfinding-service-address https://pfs.raiden.overdoze.se --flat-fee 0x6B175474E89094C44Da98b954EedeAC495271d0F 0 --proportional-fee 0x6B175474E89094C44Da98b954EedeAC495271d0F 0 --enable-monitoring --gas-price fast --proportional-imbalance-fee 0x6B175474E89094C44Da98b954EedeAC495271d0F 0 --pathfinding-max-fee 50000000000000000 --routing-mode pfs --environment-type production --default-settle-timeout 100 --default-reveal-timeout 50 --pathfinding-max-paths 5
Welcome to Raiden, version 2.0.0rc3!
[...DISCLAIMER...]
The Raiden API RPC server is now running at http://127.0.0.1:41265/.

See the Raiden documentation for all available endpoints at
https://raiden-network.readthedocs.io/en/latest/rest_api.html
Checking if the ethereum node is synchronized
You have chosen the Pathfinding Service at https://pfs.raiden.overdoze.se.
Operator: hymner, running version: 0.15.4, chain_id: 1.
Fees will be paid to 0x025dCC9F2964C1D7F886f7cB55061115e334bF56. Each request costs 0.045 RDN.
Message from the Pathfinding Service:
Overdoze PFS at your service
Raiden is running in production mode

You are connected to the 'mainnet' network and the DB path is: /home/konrad/.raiden/scenario-player/scenarios/bf1_basic_functionality/node_0023_000/node_a1362e95/netid_1/network_6d07a2ef/v27_log.db

So we know that https://github.com/raiden-network/raiden/blob/develop/raiden/ui/app.py#L410 was still reached. However we did not make it to https://github.com/raiden-network/raiden/blob/develop/raiden/ui/app.py#L423 before the 30 seconds are over.

@konradkonrad
Copy link
Contributor Author

konradkonrad commented Jun 8, 2021 •
edited
Loading

Can you try manually doing a curl request to both of the PFS' info endpoints from the SP server (ideally from within a docker container)?

I had some slowness when talking to boris' PFS and my current theory is that it's a problem with non-working IPv6.

curl -w "@curl-format.txt" -o /dev/null -s "https://pfs.raiden.overdoze.se/api/v1/info"
     time_namelookup:  0.001435s
        time_connect:  0.039997s
     time_appconnect:  0.105902s
    time_pretransfer:  0.105971s
       time_redirect:  0.000000s
  time_starttransfer:  0.148042s
                     ----------
          time_total:  0.148160s
          
curl -w "@curl-format.txt" -o /dev/null -s "https://pfs.raiden.badgateway.tech/api/v1/info"
     time_namelookup:  0.082534s
        time_connect:  0.308856s
     time_appconnect:  0.359889s
    time_pretransfer:  0.359956s
       time_redirect:  0.000000s
  time_starttransfer:  0.388109s
                     ----------
          time_total:  0.388382s

(Using this method)

@ulope
Copy link
Collaborator

ulope commented Jun 8, 2021

Ah we crossed messages. Looks like it hangs after the PFS info request. So then that's likely not the problem.

@konradkonrad
Copy link
Contributor Author

I'm reading very slow responses when connecting through httpie (i.e. with a python backend) to badgateway.tech:

# date && http https://transport.raiden.overdoze.se/health && date 
Tue Jun  8 12:39:32 PM CEST 2021
HTTP/1.1 200 OK
Content-Length: 2
Content-Type: text/plain
Date: Tue, 08 Jun 2021 10:39:41 GMT
Server: Synapse/1.33.0

OK

Tue Jun  8 12:39:33 PM CEST 2021
# <= 1 second

# date && http https://transport.raiden.badgateway.tech/health && date
Tue Jun  8 12:39:49 PM CEST 2021
HTTP/1.1 200 OK
Content-Length: 2
Content-Type: text/plain
Date: Tue, 08 Jun 2021 10:42:07 GMT
Server: Synapse/1.33.0

OK

Tue Jun  8 12:41:59 PM CEST 2021
# >= 130 seconds!!!

With curl that second request is instant

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@ulope @konradkonrad