Could not cloudify server in 10 minutes. Probably something went wrong.

[mathiasfoster]

Hello, I am trying to set up Ubicloud and running into some issues.

What I have done:

• Set up Ubicloud on my local machine so it is running on localhost:3000
• Ran docker exec -it ubicloud-app ./demo/cloudify_server
• Entered the IP address of my Hetzner server, and selected region Germany (FSN1 datacentre)
• Waited for the SSH public key to appear
• SSH into my Hetzner server which is in Rescue System, run nano /root/.ssh/authorized_keys
• Blank file. Paste the key from Ubicloud in: ssh-ed25519 A<redacted>S and leave a newline at the end of the file.
• Press enter on my local machine to continue setup.
• Sit waiting on 'Waiting for server to be cloudified' until it times out and we see the error 'Could not cloudify server in 10 minutes. Probably something went wrong.'.

What did I do wrong? How can I debug this further?
Thanks for your help!

[enescakir]

Hey @mathiasfoster, thank you for getting in touch with us!

The server should have Ubuntu 22.04 installed. However, it appears to have been in Rescue Mode in your instance. Can you try it after installing Ubuntu 22.04? You can install Ubuntu 22.04 either through the Hetzner UI or by using Hetzner's installimage script in rescue mode.

Additionally, the cloudify_server script should print the current server state during the waiting period. What was the most recent state?

[mathiasfoster]

Thanks @enescakir!

I wasn't sure whether it should be done under Rescue Mode or after installing an OS - I read the instructions closely and couldn't see anything about it, but decided it must refer to Rescue Mode in the absence of any other instructions.
My mistake!

I installed Ubuntu 22.04 through Hetzner's installimage script, and tried again by going through the steps in my first post.
After trying again, it still failed to connect to the server:

Press enter after you add the above SSH key to your machine

Waiting for server to be cloudified
2024-01-20 21:21:05 +0000 state: wait_bootstrap_rhizome

Could not cloudify server in 10 minutes. Probably something went wrong.
Last state: wait_bootstrap_rhizome. Server ID for debug: ca72a979-8a0a-8371-9684-28d4d3e3c7f7
Please check your hostname/IP address and be sure that you added the correct public SSH key to your server.
You can ask for help on GitHub discussion page: https://github.com/ubicloud/ubicloud/discussions

Is there something else I need to do to make this work?
It may be something basic!

My ubicloud instance is running on WSL2 on Windows 10, with Docker for Windows with the WSL2 integration enabled.

[enescakir]

The control plane needs to be able to connect to the server to bootstrap rhizome. I suspect that the control plane can't connect to the server. I recall a network connectivity issue from a docker container on WSL2 in the past. Could you perform the following steps to ensure connectivity?

• Checking connectivity between WSL2 and the server:

ping IP_ADDRESS_OF_SERVER

• Checking connectivity between the control plane and the server:

# Start interactive Ruby shell
docker exec -it ubicloud-app ./bin/pry

# Check connectivity. It should be able to run it
vm_host = VmHost["ca72a979-8a0a-8371-9684-28d4d3e3c7f7"]
vm_host.sshable.cmd("ls");

• If they both work, the respirate logs might have a clue

docker logs -n100 ubicloud-app

[mathiasfoster]

Thanks for these steps - here's how I went:

Check connectivity from WSL2

ping [ipv4 of server]
PING [ipv4 of server] ([ipv4 of server]) 56(84) bytes of data.
^C
--- [ipv4 of server] ping statistics ---
32 packets transmitted, 0 received, 100% packet loss, time 32217ms

I can also SSH into the server from WSL2.

Check connectivity between control plane and server

docker exec -it ubicloud-app ./bin/pry
[1] clover-development(main)> vm_host = VmHost["ca72a979-8a0a-8371-9684-28d4d3e3c7f7"]
=> #<VmHost @values={:id=>"ca72a979-8a0a-8371-9684-28d4d3e3c7f7", :allocation_state=>"unprepared", :ip6=>nil, :net6=>nil, :location=>"hetzner-fsn1", :total_mem_gib=>nil, :total_sockets=>nil, :total_cores=>nil, :total_cpus=>nil, :used_cores=>0, :ndp_needed=>false, :total_hugepages_1g=>0, :used_hugepages_1g=>0, :total_storage_gib=>nil, :available_storage_gib=>nil, :last_boot_id=>nil, :created_at=>2024-01-20 21:17:27.678034 +0000, :data_center=>nil, :arch=>nil, :total_dies=>nil}>
[2] clover-development(main)> vm_host.sshable.cmd("ls");
Net::SSH::Disconnect: connection closed by remote host
from /usr/local/bundle/gems/net-ssh-7.2.1/lib/net/ssh/transport/server_version.rb:57:in `rescue in block (2 levels) in negotiate!'
Caused by EOFError: end of file reached
from /usr/local/bundle/gems/net-ssh-7.2.1/lib/net/ssh/transport/server_version.rb:54:in `readpartial'
[3] clover-development(main)>

Respirate logs

docker logs -n100 ubicloud-app

06:50:08 respirate.1 | {"lease_acquired":{"time":"2024-01-29 06:52:08 +0000"},"message":"obtained lease","time":"2024-01-29 06:50:08 +0000","thread":"vhs9sajyca1a1jt22hn6kwf3ze"}
06:50:08 respirate.1 | {"strand":{"id":"018d28bc-6a17-8f3a-b13b-927faa768541","parent_id":"ca72a979-8a0a-8371-9684-28d4d3e3c7f7","schedule":"2024-01-29 06:50:13 +0000","lease":"2024-01-29 06:52:08 +0000","prog":"BootstrapRhizome","label":"setup","stack":[{"subject_id":"ca72a979-8a0a-8371-9684-28d4d3e3c7f7","target_folder":"host"}],"exitval":null,"retval":null,"try":1211},"strand_started":{"delay":-4.997938847,"prog_label":"BootstrapRhizome.setup"},"message":"starting strand","time":"2024-01-29 06:50:08 +0000","thread":"vhs9sajyca1a1jt22hn6kwf3ze"}
06:50:08 respirate.1 | {"strand":{"id":"018d28bc-6a17-8f3a-b13b-927faa768541","parent_id":"ca72a979-8a0a-8371-9684-28d4d3e3c7f7","schedule":"2024-01-29 06:50:13 +0000","lease":"2024-01-29 06:52:08 +0000","prog":"BootstrapRhizome","label":"setup","stack":[{"subject_id":"ca72a979-8a0a-8371-9684-28d4d3e3c7f7","target_folder":"host"}],"exitval":null,"retval":null,"try":1211},"strand_finished":{"duration":0.023733975,"prog_label":"BootstrapRhizome.setup"},"message":"finished strand","time":"2024-01-29 06:50:08 +0000","thread":"vhs9sajyca1a1jt22hn6kwf3ze"}
06:50:08 respirate.1 | {"lease_cleared":{"num_updated":1},"message":"lease cleared","time":"2024-01-29 06:50:08 +0000","thread":"vhs9sajyca1a1jt22hn6kwf3ze"}
06:50:08 respirate.1 | {"strand":{"id":"ca72a979-8a0a-8371-9684-28d4d3e3c7f7","parent_id":null,"schedule":"2024-01-29 06:50:08 +0000","lease":"2024-01-29 06:52:08 +0000","prog":"Vm::HostNexus","label":"wait_bootstrap_rhizome","stack":[{"deadline_at":"2024-01-20 21:32:33 +0000","spdk_version":"v23.09","deadline_target":"wait"}],"exitval":null,"retval":null,"try":1},"strand_finished":{"duration":0.028691287,"prog_label":"Vm::HostNexus.wait_bootstrap_rhizome"},"message":"finished strand","time":"2024-01-29 06:50:08 +0000","thread":"vhs9sajyca1a1jt22hn6kwf3ze"}
06:50:08 respirate.1 | {"lease_cleared":{"num_updated":1},"message":"lease cleared","time":"2024-01-29 06:50:08 +0000","thread":"vhs9sajyca1a1jt22hn6kwf3ze"}
06:50:08 respirate.1 | {"exception":{"message":"connection closed by remote host","class":"Net::SSH::Disconnect","backtrace":["/usr/local/bundle/gems/net-ssh-7.2.1/lib/net/ssh/transport/server_version.rb:57:in `rescue in block (2 levels) in negotiate!'","/usr/local/bundle/gems/net-ssh-7.2.1/lib/net/ssh/transport/server_version.rb:53:in `block (2 levels) in negotiate!'","/usr/local/bundle/gems/net-ssh-7.2.1/lib/net/ssh/transport/server_version.rb:52:in `loop'","/usr/local/bundle/gems/net-ssh-7.2.1/lib/net/ssh/transport/server_version.rb:52:in `block in negotiate!'","/usr/local/bundle/gems/net-ssh-7.2.1/lib/net/ssh/transport/server_version.rb:50:in `loop'","/usr/local/bundle/gems/net-ssh-7.2.1/lib/net/ssh/transport/server_version.rb:50:in `negotiate!'","/usr/local/bundle/gems/net-ssh-7.2.1/lib/net/ssh/transport/server_version.rb:33:in `initialize'","/usr/local/bundle/gems/net-ssh-7.2.1/lib/net/ssh/transport/session.rb:85:in `new'","/usr/local/bundle/gems/net-ssh-7.2.1/lib/net/ssh/transport/session.rb:85:in `initialize'","/usr/local/bundle/gems/net-ssh-7.2.1/lib/net/ssh.rb:258:in `new'","/usr/local/bundle/gems/net-ssh-7.2.1/lib/net/ssh.rb:258:in `start'","/app/lib/util.rb:14:in `rootish_ssh'","/app/prog/bootstrap_rhizome.rb:21:in `setup'","/app/model/strand.rb:109:in `public_send'","/app/model/strand.rb:109:in `block (2 levels) in unsynchronized_run'","/app/lib/sem_snap.rb:17:in `block in use'","/app/lib/sem_snap.rb:22:in `use'","/app/lib/sem_snap.rb:16:in `use'","/app/model/strand.rb:106:in `block in unsynchronized_run'","/usr/local/bundle/gems/sequel-5.76.0/lib/sequel/database/transactions.rb:235:in `block in transaction'","/usr/local/bundle/gems/sequel-5.76.0/lib/sequel/connection_pool/threaded.rb:88:in `hold'","/usr/local/bundle/gems/sequel-5.76.0/lib/sequel/database/connecting.rb:293:in `synchronize'","/usr/local/bundle/gems/sequel-5.76.0/lib/sequel/database/transactions.rb:197:in `transaction'","/app/model/strand.rb:105:in `unsynchronized_run'","/app/model/strand.rb:152:in `block (2 levels) in run'","/app/model/strand.rb:151:in `loop'","/app/model/strand.rb:151:in `block in run'","/app/model/strand.rb:36:in `take_lease_and_reload'","/app/model/strand.rb:150:in `run'","/app/prog/base.rb:177:in `map'","/app/prog/base.rb:177:in `donate'","/app/prog/vm/host_nexus.rb:49:in `wait_bootstrap_rhizome'","/app/model/strand.rb:109:in `public_send'","/app/model/strand.rb:109:in `block (2 levels) in unsynchronized_run'","/app/lib/sem_snap.rb:17:in `block in use'","/app/lib/sem_snap.rb:22:in `use'","/app/lib/sem_snap.rb:16:in `use'","/app/model/strand.rb:106:in `block in unsynchronized_run'","/usr/local/bundle/gems/sequel-5.76.0/lib/sequel/database/transactions.rb:264:in `_transaction'","/usr/local/bundle/gems/sequel-5.76.0/lib/sequel/database/transactions.rb:239:in `block in transaction'","/usr/local/bundle/gems/sequel-5.76.0/lib/sequel/connection_pool/threaded.rb:92:in `hold'","/usr/local/bundle/gems/sequel-5.76.0/lib/sequel/database/connecting.rb:293:in `synchronize'","/usr/local/bundle/gems/sequel-5.76.0/lib/sequel/database/transactions.rb:197:in `transaction'","/app/model/strand.rb:105:in `unsynchronized_run'","/app/model/strand.rb:152:in `block (2 levels) in run'","/app/model/strand.rb:151:in `loop'","/app/model/strand.rb:151:in `block in run'","/app/model/strand.rb:36:in `take_lease_and_reload'","/app/model/strand.rb:150:in `run'","/app/scheduling/dispatcher.rb:48:in `block in start_strand'"],"cause":"#<EOFError: end of file reached>"},"message":"exception terminates thread","time":"2024-01-29 06:50:08 +0000","thread":"vhs9sajyca1a1jt22hn6kwf3ze"}
06:50:08 respirate.1 | {"exception":{"message":"end of file reached","class":"EOFError","backtrace":["/usr/local/bundle/gems/net-ssh-7.2.1/lib/net/ssh/transport/server_version.rb:54:in `readpartial'","/usr/local/bundle/gems/net-ssh-7.2.1/lib/net/ssh/transport/server_version.rb:54:in `block (2 levels) in negotiate!'","/usr/local/bundle/gems/net-ssh-7.2.1/lib/net/ssh/transport/server_version.rb:52:in `loop'","/usr/local/bundle/gems/net-ssh-7.2.1/lib/net/ssh/transport/server_version.rb:52:in `block in negotiate!'","/usr/local/bundle/gems/net-ssh-7.2.1/lib/net/ssh/transport/server_version.rb:50:in `loop'","/usr/local/bundle/gems/net-ssh-7.2.1/lib/net/ssh/transport/server_version.rb:50:in `negotiate!'","/usr/local/bundle/gems/net-ssh-7.2.1/lib/net/ssh/transport/server_version.rb:33:in `initialize'","/usr/local/bundle/gems/net-ssh-7.2.1/lib/net/ssh/transport/session.rb:85:in `new'","/usr/local/bundle/gems/net-ssh-7.2.1/lib/net/ssh/transport/session.rb:85:in `initialize'","/usr/local/bundle/gems/net-ssh-7.2.1/lib/net/ssh.rb:258:in `new'","/usr/local/bundle/gems/net-ssh-7.2.1/lib/net/ssh.rb:258:in `start'","/app/lib/util.rb:14:in `rootish_ssh'","/app/prog/bootstrap_rhizome.rb:21:in `setup'","/app/model/strand.rb:109:in `public_send'","/app/model/strand.rb:109:in `block (2 levels) in unsynchronized_run'","/app/lib/sem_snap.rb:17:in `block in use'","/app/lib/sem_snap.rb:22:in `use'","/app/lib/sem_snap.rb:16:in `use'","/app/model/strand.rb:106:in `block in unsynchronized_run'","/usr/local/bundle/gems/sequel-5.76.0/lib/sequel/database/transactions.rb:235:in `block in transaction'","/usr/local/bundle/gems/sequel-5.76.0/lib/sequel/connection_pool/threaded.rb:88:in `hold'","/usr/local/bundle/gems/sequel-5.76.0/lib/sequel/database/connecting.rb:293:in `synchronize'","/usr/local/bundle/gems/sequel-5.76.0/lib/sequel/database/transactions.rb:197:in `transaction'","/app/model/strand.rb:105:in `unsynchronized_run'","/app/model/strand.rb:152:in `block (2 levels) in run'","/app/model/strand.rb:151:in `loop'","/app/model/strand.rb:151:in `block in run'","/app/model/strand.rb:36:in `take_lease_and_reload'","/app/model/strand.rb:150:in `run'","/app/prog/base.rb:177:in `map'","/app/prog/base.rb:177:in `donate'","/app/prog/vm/host_nexus.rb:49:in `wait_bootstrap_rhizome'","/app/model/strand.rb:109:in `public_send'","/app/model/strand.rb:109:in `block (2 levels) in unsynchronized_run'","/app/lib/sem_snap.rb:17:in `block in use'","/app/lib/sem_snap.rb:22:in `use'","/app/lib/sem_snap.rb:16:in `use'","/app/model/strand.rb:106:in `block in unsynchronized_run'","/usr/local/bundle/gems/sequel-5.76.0/lib/sequel/database/transactions.rb:264:in `_transaction'","/usr/local/bundle/gems/sequel-5.76.0/lib/sequel/database/transactions.rb:239:in `block in transaction'","/usr/local/bundle/gems/sequel-5.76.0/lib/sequel/connection_pool/threaded.rb:92:in `hold'","/usr/local/bundle/gems/sequel-5.76.0/lib/sequel/database/connecting.rb:293:in `synchronize'","/usr/local/bundle/gems/sequel-5.76.0/lib/sequel/database/transactions.rb:197:in `transaction'","/app/model/strand.rb:105:in `unsynchronized_run'","/app/model/strand.rb:152:in `block (2 levels) in run'","/app/model/strand.rb:151:in `loop'","/app/model/strand.rb:151:in `block in run'","/app/model/strand.rb:36:in `take_lease_and_reload'","/app/model/strand.rb:150:in `run'","/app/scheduling/dispatcher.rb:48:in `block in start_strand'"],"cause":"nil"},"message":"nested exception","time":"2024-01-29 06:50:08 +0000","thread":"vhs9sajyca1a1jt22hn6kwf3ze"}
 ... and continues

[enescakir]

I looks like your WSL and docker image can't connect to the server.

• The packet loss is 100% 32 packets transmitted, 0 received, 100% packet loss, time 32217ms
• The pry can't connect Net::SSH::Disconnect: connection closed by remote host
• The respirate can't connect Net::SSH::Disconnect: connection closed by remote host, end of file reached

[enescakir]

You might check connectivity of our WSL docker setup with a simple alpine image

docker run -it alpine sh

ping google.com
ping IP_ADDRESS_OF_SERVER

ssh root@IP_ADDRESS_OF_SERVER

[adelorenzo-portainer]

Hello, I am facing the same issue. My docker image does have access to the server (running on Hetzner, Finland). I ran some tests and there is connectivity. The cloudify script manages to install the required packages for the console but after some time it just hangs there and spits out the Could not cloudify server in 10 minutes. Probably something went wrong message.

My console is running on my mac laptop.

Thanks

[enescakir]

Hi @adelorenzo-portainer, the cloudify_server script should print the current server state during the waiting period. What was the most recent state?

[adelorenzo-portainer]

Hello @enescakir,

This is the message I got after 10 minutes:

Could not cloudify server in 10 minutes. Probably something went wrong.
Last state: wait_prep. Server ID for debug: 506a6e14-325f-8371-87e4-169907fd389c
Please check your hostname/IP address and be sure that you added the correct public SSH key to your server.
You can ask for help on GitHub discussion page: https://github.com/ubicloud/ubicloud/discussions

It's weird because the host gets modified. When I log in I see the Ubicloud banner and the new hostname:

       _     _      _                 _
 _   _| |__ (_) ___| | ___  _   _  __| |
| | | |  _ \| |/ __| |/ _ \| | | |/ _  |
| |_| | |_) | | (__| | (_) | |_| | (_| |
 \__,_|_.__/|_|\___|_|\___/ \__,_|\__,_|

Thanks.

[enescakir]

We recently fixed a bug in the SetupNftables. Probably, it stuck at wait_prep because of it
#1386

[adelorenzo-portainer]

Hello @enescakir,

I started again from scratch. I deployed ubicloud this time on a Linux machine running docker. I reset the Hetzner host (for nth time) with Ubuntu 20.04 and then 22.04. In both cases the result was the same:

Press enter after you add the above SSH key to your machine

Waiting for server to be cloudified
2024-03-27 17:35:08 +0000 state: wait_bootstrap_rhizome
2024-03-27 17:35:36 +0000 state: wait_prep

Could not cloudify server in 10 minutes. Probably something went wrong.
Last state: wait_prep. Server ID for debug: f6cca0f9-6fac-8371-a7dd-da907599b213
Please check your hostname/IP address and be sure that you added the correct public SSH key to your server.
You can ask for help on GitHub discussion page: https://github.com/ubicloud/ubicloud/discussions

In both attempts, the host received the updates:

       _     _      _                 _
 _   _| |__ (_) ___| | ___  _   _  __| |
| | | |  _ \| |/ __| |/ _ \| | | |/ _  |
| |_| | |_) | | (__| | (_) | |_| | (_| |
 \__,_|_.__/|_|\___|_|\___/ \__,_|\__,_|

Last login: Wed Mar 27 17:43:25 2024 from 152.231.128.107
[root@vhyv6a1ybfnj1mzexn43nk6s16 ~]#

Any other ideas?

Thanks

[byucesoy]

Hi @adelorenzo-portainer,
I'll make some improvements on our docker images including making it easier to use. I'd like to understand the problem you are hitting better, so that the next iteration of it would work out of the box. Do you have some time to look into this and debug together using a video call? You can reach out to me from <my-first-name, which you can find it on my github profile>@ubicloud.com to schedule a time.

[byucesoy]

Just to close the discussion. We looked this together and after ensuring latest docker image is used, cloudifying worked as expected and we didn't hit any issue. We were not sure what was the cause of the original problem.