Deploy to GCE fails at cloud-init (Timeout when waiting for file /var/lib/cloud/data/result.json)

[rvignacio]

Hello, I have been able to deploy Algo to GCE several times before but I am getting the following error now:

TASK [Wait 600 seconds for target connection to become reachable/usable] ***********************************************************************************************************
ok: [localhost -> x.x.x.x] => (item=x.x.x.x)

PLAY [Configure the server and install required software] **************************************************************************************************************************

TASK [Wait until the cloud-init completed] *****************************************************************************************************************************************
fatal: [x.x.x.x]: FAILED! => {"changed": false, "elapsed": 600, "msg": "Timeout when waiting for file /var/lib/cloud/data/result.json"}

TASK [include_tasks] ***************************************************************************************************************************************************************
included: /home/ignacio/algo/playbooks/rescue.yml for x.x.x.x

TASK [debug] ***********************************************************************************************************************************************************************
ok: [x.x.x.x] => {
    "fail_hint": [
        "Sorry, but something went wrong!",
        "Please check the troubleshooting guide.",
        "https://trailofbits.github.io/algo/troubleshooting.html"
    ]
}

TASK [Fail the installation] *******************************************************************************************************************************************************
fatal: [x.x.x.x]: FAILED! => {"changed": false, "msg": "Failed as requested from task"}

PLAY RECAP *************************************************************************************************************************************************************************
x.x.x.x             : ok=2    changed=0    unreachable=0    failed=1    skipped=0    rescued=1    ignored=0
localhost                  : ok=49   changed=12   unreachable=0    failed=0    skipped=4    rescued=0    ignored=0

If I ssh into the VM, the file /var/cloud/data/result.json exists and has this content:

{
 "v1": {
  "datasource": "DataSourceGCELocal",
  "errors": []
 }
}

These are my options:

Algo running on: Debian GNU/Linux 11 (bullseye) (Virtualized: kvm)
Created from git clone. Last commit: 8b05cda Fix OS Name for Vultr (#14458)
Python 3.9.2
Runtime variables:
    algo_provider "gce"
    algo_ondemand_cellular "True"
    algo_ondemand_wifi "True"
    algo_ondemand_wifi_exclude "*****"
    algo_dns_adblocking "False"
    algo_ssh_tunneling "False"
    wireguard_enabled "True"
    dns_encryption "True"

Any suggestions on what to debug? I have tried updating the timeout value in https://github.com/trailofbits/algo/blob/master/server.yml#L14 hoping it only needed more time, but still fails.

Thanks!

[davidemyers]

When you SSH into the VPS has SSH been moved to port 4160 or is it still on 22?

Are there any obvious errors in /var/log/cloud-init-output.log?

[rvignacio]

SSH is listening at 4160 as expected.

Checked /var/log/cloud-init-output.log but it does not have any errors. It is able to generate keys, update/install packages. It finishes with:

Cloud-init v. 22.1-14-g2e17a0d6-0ubuntu1~20.04.3 running 'modules:final' at Thu, 19 May 2022 00:10:43 +0000. Up 28.41 seconds.
Cloud-init v. 22.1-14-g2e17a0d6-0ubuntu1~20.04.3 finished at Thu, 19 May 2022 00:24:13 +0000. Datasource DataSourceGCELocal.  Up 838.71 seconds

Tried several times in which I opened a second terminal and SSH'd into the VM. There seem to be some race condition going on.

In the end, I changed this:
https://github.com/trailofbits/algo/blob/master/server.yml#L9-L17
to

    - block:
      - name: Wait until the cloud-init completed
        wait_for:
          timeout: 600
        become: false
        when: cloudinit

So that it would only sleep instead of checking the file, and it eventually worked.

Looks like cloud-init is taking 850 ~ 900 seconds to finish. But if I change that timeout to anything other than 600 then the installer gets stalled. While 600 is not enough, when it tries to install more packages it eventually catches up and is able to continue.

I will keep digging, but for now I was able to deploy a server at least. Thanks for the heads up about the logs!

[rvignacio]

Update: after a few months, I tried to create a new server in GCE and everything worked on the first attempt without having to apply the timeout change. Maybe the ansible update did the trick. I will update this discussion as answered as problem does not happen anymore.