[Q&A] Real-world failure: RuntimeError: Failed to get engine\n The client could not register to server.

[Ultimate-Storm]

Python version (python3 -V)

3.10

NVFlare version (python3 -m pip list | grep "nvflare")

2.4.0

NVFlare branch (if running examples, please use the branch that corresponds to the NVFlare version, git branch)

2.4.0

Operating system

Ubuntu 22.04.4 LTS

Have you successfully run any of the following examples?

• hello-numpy-sag with simulator
• hello-pt with simulator
• hello-numpy-sag with POC
• hello-pt with POC

Please describe your question

I run into the following error when trying to connect a remote client to a server. I have the setup with two separate machines connected within lab network. Provision is configured through Dashboard. Two clients have been registered. Project is running under conda environment and I have ensured that they are identical across the two machines. I checked I have no problem to access dl3.example.com on port 8002 and 8003 from 'dl0'
I have already tried POC on a single machine to host the server, admin, and two clients locally and everything is running fine. But now I have machine 'dl3' hosting server and one client, 'dl0' hosting another client. In this case I failed to connect the client from 'dl0' to the server. Here is the error log from 'dl0'

dl0:~/Downloads/remote_dl0/startup$ WORKSPACE set to /home/swarm/Downloads/remote_dl0/startup/..
PYTHONPATH is /local/custom:
start fl because process of 24105 does not exist
new pid 7693
Waiting for SP....
2024-05-22 11:13:51,165 - CoreCell - INFO - remote_dl0: created backbone external connector to grpc://dl3.example.com:8002
2024-05-22 11:13:51,165 - ConnectorManager - INFO - 7693: Try start_listener Listener resources: {'secure': False, 'host': 'localhost'}
2024-05-22 11:13:51,166 - nvflare.fuel.f3.sfm.conn_manager - INFO - Connector [CH00002 PASSIVE tcp://0:19598] is starting
2024-05-22 11:13:51,667 - CoreCell - INFO - remote_dl0: created backbone internal listener for tcp://localhost:19598
2024-05-22 11:13:51,668 - nvflare.fuel.f3.sfm.conn_manager - INFO - Connector [CH00001 ACTIVE grpc://dl3.example.com:8002] is starting
2024-05-22 11:13:51,669 - FederatedClient - INFO - Wait for engine to be created.
2024-05-22 11:13:51,691 - nvflare.fuel.f3.drivers.grpc_driver.GrpcDriver - INFO - created secure channel at dl3.example.com:8002
2024-05-22 11:13:51,691 - nvflare.fuel.f3.sfm.conn_manager - INFO - Connection [CN00002 N/A => dl3.example.com:8002] is created: PID: 7693
Exception in thread Thread-1 (_rnq_worker):
Traceback (most recent call last):
File "/usr/lib/python3.10/threading.py", line 1016, in _bootstrap_inner
self.run()
File "/usr/lib/python3.10/threading.py", line 953, in run
self._target(*self._args, **self._kwargs)
File "/home/swarm/.local/lib/python3.10/site-packages/nvflare/ha/dummy_overseer_agent.py", line 112, in _rnq_worker
self._do_callback()
File "/home/swarm/.local/lib/python3.10/site-packages/nvflare/ha/dummy_overseer_agent.py", line 106, in _do_callback
self._update_callback(self)
File "/home/swarm/.local/lib/python3.10/site-packages/nvflare/private/fed/client/fed_client_base.py", line 147, in overseer_callback
self.set_primary_sp(sp)
File "/home/swarm/.local/lib/python3.10/site-packages/nvflare/private/fed/client/fed_client_base.py", line 362, in set_primary_sp
return self.set_sp(self._get_project_name(), sp)
File "/home/swarm/.local/lib/python3.10/site-packages/nvflare/private/fed/client/fed_client_base.py", line 162, in set_sp
self._create_cell(location, scheme)
File "/home/swarm/.local/lib/python3.10/site-packages/nvflare/private/fed/client/fed_client_base.py", line 220, in _create_cell
raise RuntimeError(f"Failed to get engine after {time.time()-start} seconds")
RuntimeError: Failed to get engine after 15.0006685256958 seconds
The client could not register to server.
2024-05-22 11:14:22,095 - MPM - ERROR - Execute exception: RuntimeError: Login failed.
2024-05-22 11:14:22,096 - MPM - ERROR - Traceback (most recent call last):
File "/home/swarm/.local/lib/python3.10/site-packages/nvflare/fuel/f3/mpm.py", line 154, in run
rc = main_func(**kwargs)
File "/home/swarm/.local/lib/python3.10/site-packages/nvflare/private/fed/app/client/client_train.py", line 120, in main
raise RuntimeError("Login failed.")
RuntimeError: Login failed.

Log from 'dl3' server:

dl3:~/Downloads/dl3.example.com/startup$ WORKSPACE set to /home/swarm/Downloads/dl3.example.com/startup/..
start fl because of no pid.fl
new pid 6169
2024-05-21 16:23:47,511 - CoreCell - INFO - server: creating listener on grpc://0:8002
2024-05-21 16:23:47,521 - CoreCell - INFO - server: created backbone external listener for grpc://0:8002
2024-05-21 16:23:47,521 - ConnectorManager - INFO - 6169: Try start_listener Listener resources: {'secure': False, 'host': 'localhost'}
2024-05-21 16:23:47,522 - nvflare.fuel.f3.sfm.conn_manager - INFO - Connector [CH00002 PASSIVE tcp://0:14633] is starting
2024-05-21 16:23:48,023 - CoreCell - INFO - server: created backbone internal listener for tcp://localhost:14633
2024-05-21 16:23:48,023 - nvflare.fuel.f3.sfm.conn_manager - INFO - Connector [CH00001 PASSIVE grpc://0:8002] is starting
deployed FL server trainer.
2024-05-21 16:23:48,049 - nvflare.fuel.hci.server.hci - INFO - Starting Admin Server dl3.example.com on Port 8003
2024-05-21 16:23:48,049 - root - INFO - Server started
2024-05-21 16:23:48,052 - nvflare.fuel.f3.drivers.grpc_driver.Server - INFO - added secure port at 0.0.0.0:8002
2024-05-21 16:23:53,031 - ServerState - INFO - Got the primary sp: dl3.example.com fl_port: 8002 SSID: ebc6125d-0a56-4688-9b08-355fe9e4d61a. Turning to hot.
2024-05-21 16:34:02,512 - nvflare.fuel.f3.sfm.conn_manager - INFO - Connection [CN00002 0.0.0.0:8002 <= ipv4:127.0.0.1:43776 SSL dl3] is created: PID: 6169
2024-05-21 16:34:02,864 - ClientManager - INFO - Client: New client dl3@192.168.33.103 joined. Sent token: 34fe6580-29ee-44e5-b200-6db8ac6fffaf. Total clients: 1
2024-05-22 10:07:39,567 - nvflare.fuel.f3.sfm.conn_manager - INFO - Connection [CN00002 Not Connected] is closed PID: 6169
2024-05-22 10:07:51,534 - nvflare.fuel.f3.sfm.conn_manager - INFO - Connection [CN00003 0.0.0.0:8002 <= ipv4:127.0.0.1:43784 SSL dl3] is created: PID: 6169
2024-05-22 10:07:51,896 - ClientManager - INFO - Client: dl3 already registered. Re-login the client with a new token.
2024-05-22 10:07:51,896 - ClientManager - INFO - Client: New client dl3@192.168.33.103 joined. Sent token: 3e2aad19-dd3a-44fb-9b30-ff997e37e4ca. Total clients: 1
E0522 10:11:26.975925425 6216 ssl_transport_security.cc:1501] Handshake failed with fatal error SSL_ERROR_SSL: error:100000f7:SSL routines:OPENSSL_internal:WRONG_VERSION_NUMBER.
2024-05-22 10:20:58,785 - nvflare.fuel.f3.sfm.conn_manager - INFO - Connection [CN00004 0.0.0.0:8002 <= ipv4:127.0.0.1:43788 SSL local_dl0] is created: PID: 6169
2024-05-22 10:20:59,148 - ClientManager - INFO - Client: New client local_dl0@192.168.33.103 joined. Sent token: 7c56c702-ebd8-4624-bc27-1819e12d99ce. Total clients: 2

The above 'Total clients: 2' is because I tried to start the second local client on 'dl3' instead of the remote one just for testing.

Log from 'dl3' client:

dl3:~/Downloads/dl3/startup$ WORKSPACE set to /home/swarm/Downloads/dl3/startup/..
PYTHONPATH is /local/custom:
start fl because of no pid.fl
new pid 66833
Waiting for SP....
2024-05-22 10:07:51,012 - CoreCell - INFO - dl3: created backbone external connector to grpc://dl3.example.com:8002
2024-05-22 10:07:51,012 - ConnectorManager - INFO - 66833: Try start_listener Listener resources: {'secure': False, 'host': 'localhost'}
2024-05-22 10:07:51,013 - nvflare.fuel.f3.sfm.conn_manager - INFO - Connector [CH00002 PASSIVE tcp://0:49803] is starting
2024-05-22 10:07:51,514 - CoreCell - INFO - dl3: created backbone internal listener for tcp://localhost:49803
2024-05-22 10:07:51,514 - nvflare.fuel.f3.sfm.conn_manager - INFO - Connector [CH00001 ACTIVE grpc://dl3.example.com:8002] is starting
2024-05-22 10:07:51,516 - FederatedClient - INFO - Wait for engine to be created.
2024-05-22 10:07:51,523 - nvflare.fuel.f3.drivers.grpc_driver.GrpcDriver - INFO - created secure channel at dl3.example.com:8002
2024-05-22 10:07:51,523 - nvflare.fuel.f3.sfm.conn_manager - INFO - Connection [CN00002 N/A => dl3.example.com:8002] is created: PID: 66833
2024-05-22 10:07:51,898 - FederatedClient - INFO - Successfully registered client:dl3 for project DUKE_NVFLARE_SL. Token:3e2aad19-dd3a-44fb-9b30-ff997e37e4ca SSID:ebc6125d-0a56-4688-9b08-355fe9e4d61a
2024-05-22 10:07:51,904 - FederatedClient - INFO - Got engine after 0.38811469078063965 seconds
2024-05-22 10:07:51,904 - FederatedClient - INFO - Got the new primary SP: grpc://dl3.example.com:8002

Any help is appreciated!

[Ultimate-Storm]

I just tried to manually set up provison with the project.yaml attached, also got the same error message only on the remote client.

[YuanTingHsieh]

@Ultimate-Storm thanks for sharing your issue and logs.

You mentioned you have set up provision with this new project.yaml, can you share the logs (server, both clients) as well?
Another question, where did you setup the server and client machines? Are they both in your physical location? Or you use cloud services?
"I checked I have no problem to access dl3.example.com on port 8002 and 8003 from 'dl0'" How did you check this?

Thanks!

[Ultimate-Storm]

Hi, thanks for your reply. I don't have access to the logs by manually setting up with project.yaml. But they are the same as what I have attached.
The machines are in the same physical location.
Connection check logs from dl0:

nc -zv dl3.tud.de 8002
nc -zv dl3.tud.de 8003
Connection to dl3.tud.de (192.168.33.103) 8002 port [tcp/*] succeeded!
Connection to dl3.tud.de (192.168.33.103) 8003 port [tcp/*] succeeded!

[YuanTingHsieh]

@Ultimate-Storm sorry to get back to you this late.
What if you use "dl3.tud.de" instead of "dl3.example.com"?

You should have some logs when you start the system, if you can share we might be able to get more insights.

[Ultimate-Storm]

This is what I got after changing the hostname:

dl2:/startupkit/startup$ WORKSPACE set to /startupkit/startup/..
PYTHONPATH is /local/custom:/workspace/controller
start fl because of no pid.fl
new pid 17
2024-10-17 12:23:05,173 - matplotlib - WARNING - Matplotlib created a temporary cache directory at /tmp/matplotlib-2umzekzf because the default path (/home/swarm/.config/matplotlib) is not a writable directory; it is highly recommended to set the MPLCONFIGDIR environment variable to a writable directory, in particular to speed up the import of Matplotlib and to better support multiprocessing.
2024-10-17 12:23:05,316 - matplotlib.font_manager - INFO - generated new fontManager
Waiting for SP....
2024-10-17 12:23:07,592 - CoreCell - INFO - dl0: created backbone external connector to grpc://dl3.tud.de:8002
2024-10-17 12:23:07,592 - ConnectorManager - INFO - 17: Try start_listener Listener resources: {'secure': False, 'host': 'localhost'}
2024-10-17 12:23:07,593 - nvflare.fuel.f3.sfm.conn_manager - INFO - Connector [CH00002 PASSIVE tcp://0:60856] is starting
2024-10-17 12:23:08,094 - CoreCell - INFO - dl0: created backbone internal listener for tcp://localhost:60856
2024-10-17 12:23:08,095 - nvflare.fuel.f3.sfm.conn_manager - INFO - Connector [CH00001 ACTIVE grpc://dl3.tud.de:8002] is starting
2024-10-17 12:23:08,096 - FederatedClient - INFO - Wait for engine to be created.
2024-10-17 12:23:08,106 - nvflare.fuel.f3.drivers.grpc_driver.GrpcDriver - INFO - created secure channel at dl3.tud.de:8002
2024-10-17 12:23:08,107 - nvflare.fuel.f3.sfm.conn_manager - INFO - Connection [CN00002 N/A => dl3.tud.de:8002] is created: PID: 17
Exception in thread Thread-2 (_rnq_worker):
Traceback (most recent call last):
File "/opt/conda/lib/python3.10/threading.py", line 1016, in _bootstrap_inner
self.run()
File "/opt/conda/lib/python3.10/threading.py", line 953, in run
self._target(*self._args, **self._kwargs)
File "/opt/conda/lib/python3.10/site-packages/nvflare/ha/dummy_overseer_agent.py", line 112, in _rnq_worker
self._do_callback()
File "/opt/conda/lib/python3.10/site-packages/nvflare/ha/dummy_overseer_agent.py", line 106, in _do_callback
self._update_callback(self)
File "/opt/conda/lib/python3.10/site-packages/nvflare/private/fed/client/fed_client_base.py", line 147, in overseer_callback
self.set_primary_sp(sp)
File "/opt/conda/lib/python3.10/site-packages/nvflare/private/fed/client/fed_client_base.py", line 362, in set_primary_sp
return self.set_sp(self._get_project_name(), sp)
File "/opt/conda/lib/python3.10/site-packages/nvflare/private/fed/client/fed_client_base.py", line 162, in set_sp
self._create_cell(location, scheme)
File "/opt/conda/lib/python3.10/site-packages/nvflare/private/fed/client/fed_client_base.py", line 220, in _create_cell
raise RuntimeError(f"Failed to get engine after {time.time()-start} seconds")
RuntimeError: Failed to get engine after 15.000895977020264 seconds
The client could not register to server.
2024-10-17 12:23:38,499 - MPM - ERROR - Execute exception: RuntimeError: Login failed.
2024-10-17 12:23:38,500 - MPM - ERROR - Traceback (most recent call last):
File "/opt/conda/lib/python3.10/site-packages/nvflare/fuel/f3/mpm.py", line 154, in run
rc = main_func(**kwargs)
File "/opt/conda/lib/python3.10/site-packages/nvflare/private/fed/app/client/client_train.py", line 120, in main
raise RuntimeError("Login failed.")
RuntimeError: Login failed.
2024-10-17 12:23:40,004 - nvflare.fuel.f3.sfm.conn_manager - INFO - Connection [CN00002 Not Connected] is closed PID: 17
2024-10-17 12:23:40,131 - nvflare.fuel.f3.drivers.grpc_driver.GrpcDriver - INFO - CLIENT: finished connection [CN00002 Not Connected]
2024-10-17 12:23:40,132 - MPM - INFO - MPM: Good Bye!