Repository: dask/dask-cloudprovider (language: python)

Issue:
AzureVMCluster constructor just hangs after creating the scheduler. 


**What happened**:

After creating a new cluster with the AzureVMCluster constructor, the run  just hangs after creating the scheduler. 

In the Azure Portal one can see the scheduler after it is created, it runs for a couple of minutes then it is stopped, presumably an indication that something went wrong, but the run does not fail, it just hangs

**What you expected to happen**:
The cluster to be created with the number of workers specified

**Minimal Complete Verifiable Example**:
In a new Conda environment

pip install dask-cloudprovider[azure] 
az login


```python
from dask_cloudprovider.azure import AzureVMCluster
resource_group = "NGC-AML-Quick-Launch"
workspace_name = "NGC_AML_Quick_Launch_WS"
vnet="NGC-AML-Quick-Launch-vnet"
security_group="NGC-AML-Quick-Launch-nsg"
initial_node_count = 2
vm_size = "Standard_NC6s_v3"
location = "South Central US"
base_dockerfile = "rapidsai/rapidsai-core:cuda10.2-runtime-ubuntu18.04-py3.8"
base_dockerfile = "rapidsai/rapidsai-core-dev-nightly:0.18-cuda10.2-devel-ubuntu18.04-py3.8"
env_vars = {"EXTRA_CONDA_PACKAGES":"pywin32","EXTRA_PIP_PACKAGES": "dask-cloudprovider[azure] dask-cloudprovider[azure] --upgrade  gcsfs dask_xgboost azureml"}
env_vars = {"EXTRA_PIP_PACKAGES": "dask-cloudprovider[azure]"}

cluster = AzureVMCluster(
resource_group=resource_group,
location = location,
vnet=vnet,
security_group=security_group,
n_workers=initial_node_count,
vm_size=vm_size,
docker_image=base_dockerfile,
docker_args="--privileged",
security=False,
env_vars=env_vars,
worker_class="dask_cuda.CUDAWorker")
```

**Anything else we need to know?**:
![Screenshot (16)](https://user-images.githubusercontent.com/39012886/107569055-b58e3c80-6b9c-11eb-9a78-b4fbe4f7a831.png)

VM dask-7984db15-scheduler is created and can be seen on the Azure Portal, it runs for a few minutes then it is closed, but the run never crashes it just hangs

**Environment**:

- Dask version:
 2021.02.0
- Python version:
   3.8
- Operating System:
windows
- Install method (conda, pip, source):
pip


Discussion / hints:
Is there any debug information or logs from the node ?  Did the image fail to download ?
@quasiben I looked at the logs from the scheduler VM and all I could find was the event that the VM was stooped
"This virtual machine is stopping and deallocating as requested by an authorized user or process" with no explanation as of why. 

I did try to load the image into an Azure VM I set up manually and it actually failed to load with a "no space left on device" problem.  
I have seen the hanging issue before. Specifically when I tried to use: env_vars = {"EXTRA_PIP_PACKAGES": "dask-cloudprovider[azure] gcsfs dask_xgboost azureml"}, as opposed to just env_vars = {"EXTRA_PIP_PACKAGES": "dask-cloudprovider[azure]"}, same result the scheduler was created and later stopped. I assumed that was a format issue but still the run just hanged without any indication that anything was wrong

I may be having a similar issue.

I have been trying to get extra packages into my workers, but when I do this it hangs forever/
I have an environment.yml for conda, but from what I've seen the 'correct' way is to use environment variables to pass the package names to the VMs, so I parse the environment.yml and put it in a string.

I've also tried making my own docker image, but haven't had any success - but this is a separate issue.

This hangs forever.

python:
```
EXTRA_CONDA_PACKAGES = "cartopy=0.18.0 dask gcsfs geopandas=0.8.1 hdf5 libnetcdf numba pandas pip scipy xarray>=0.16.1"
EXTRA_PIP_PACKAGES = "dask-cloudprovider[azure] descartes fiona intake intake-esm jupyter jupytext matplotlib nbconvert nc-time-axis psychrolib==2.5.0"

from dask_cloudprovider.azure import AzureVMCluster
cluster = AzureVMCluster(resource_group="PangeoHarvestOccupationalHeat",
                         vnet="PangeoHOH-vnet",
                         security_group="PangeoHOH-sg",
                         location="UK South",
                         env_vars={"EXTRA_PIP_PACKAGES": EXTRA_PIP_PACKAGES, "EXTRA_CONDA_PACKAGES": EXTRA_CONDA_PACKAGES},
                         n_workers=1)
```

Result:
```
Creating scheduler instance
Assigned public IP
Network interface ready
Creating VM
Created VM dask-e2b3fc03-scheduler
Waiting for scheduler to run
```

Version info:
```
dask                      2021.1.1           pyhd8ed1ab_0    conda-forge
dask-cloudprovider        0.5.1                    pypi_0    pypi
dask-core                 2021.1.1           pyhd8ed1ab_0    conda-forge
```
@manuelreyesgomez in your output I see something problematic

> dll load failed while importing pywin32

I don't think this should be an issue.  For both of you, can you try `auto_shutdown=False` and then can you paste output from: `/var/log/cloud-init.log`. @jacobtomlinson and I have talked a bit about how best to access/expose these logs for cases such as this
I just tried this, and looked in `/var/log/cloud-init.log`, but don't see anything in there with a recent date.
Can you also inspect `/var/log/cloud-init-output.log` ?  Or any other cloud-init* logs in /var/log ?  

Oh!  Also, with auth_shutdown=False you should ensure that dask-cloudprovider does indeed close the machine when exiting the process or a call to `cluster.shutdown()`
`cluster.shutdown()` does not work, because `cluster = AzureVMCluster(...)` hangs forever and does not return.
There are no other cloud-init* logs in /var/log that have been written to recently.
@quasiben  that warning

dll load failed while importing pywin32

Appears even when the constructor had succeeded on other runs
(It might be a windows related issue)


@quasiben I ran it again, this time using the Windows Subsystem for Linux and the 

dll load failed while importing pywin32

warning did not appear

It still hangs but the VM scheduler is NOT stopped, it keeps running, which is worst as the user would be billed if it stays running and the user fails to do a manual stop

I did use auto_shutdown=False  but I could not find anything relevant on /var/log

Coming back to this -- sorry for the delay.  Has a security group been defined which allows for 8786 and 8787 to be accessible ?

xref: https://cloudprovider.dask.org/en/latest/azure.html#security-groups
Finally up and running on azure.  I see the following in `/var/log/cloud-init-output.log`:

```
Preparing to unpack .../nvidia-docker2_2.5.0-1_all.deb ...
Unpacking nvidia-docker2 (2.5.0-1) ...
Setting up libnvidia-container1:amd64 (1.3.3-1) ...
Setting up libnvidia-container-tools (1.3.3-1) ...
Setting up nvidia-container-toolkit (1.4.2-1) ...
Setting up nvidia-container-runtime (3.4.2-1) ...
Setting up nvidia-docker2 (2.5.0-1) ...
Processing triggers for libc-bin (2.27-3ubuntu1.4) ...
WARNING: Error loading config file: .dockercfg: $HOME is not defined
Unable to find image 'descartes:latest' locally
docker: Error response from daemon: pull access denied for descartes, repository does not exist or may require 'docker login': denied: requested access to the resource is denied.
See 'docker run --help'.
Cloud-init v. 20.4.1-0ubuntu1~18.04.1 running 'modules:final' at Wed, 17 Feb 2021 19:59:18 +0000. Up 498.01 seconds.
2021-02-17 20:02:16,475 - cc_scripts_user.py[WARNING]: Failed to run module scripts-user (scripts in /var/lib/cloud/instance/scripts)
2021-02-17 20:02:16,486 - util.py[WARNING]: Running module scripts-user (<module 'cloudinit.config.cc_scripts_user' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_scripts_user.py'>) failed
ci-info: no authorized SSH keys fingerprints found for user dask.
Cloud-init v. 20.4.1-0ubuntu1~18.04.1 finished at Wed, 17 Feb 2021 20:02:16 +0000. Datasource DataSourceAzure [seed=/dev/sr0].  Up 676.60 seconds
```
> 
> 
> Coming back to this -- sorry for the delay. Has a security group been defined which allows for 8786 and 8787 to be accessible ?
> 
> xref: https://cloudprovider.dask.org/en/latest/azure.html#security-groups

Yes in my case
> Finally up and running on azure. I see the following in `/var/log/cloud-init-output.log`:
> 
> ```
> Preparing to unpack .../nvidia-docker2_2.5.0-1_all.deb ...
> Unpacking nvidia-docker2 (2.5.0-1) ...
> Setting up libnvidia-container1:amd64 (1.3.3-1) ...
> Setting up libnvidia-container-tools (1.3.3-1) ...
> Setting up nvidia-container-toolkit (1.4.2-1) ...
> Setting up nvidia-container-runtime (3.4.2-1) ...
> Setting up nvidia-docker2 (2.5.0-1) ...
> Processing triggers for libc-bin (2.27-3ubuntu1.4) ...
> WARNING: Error loading config file: .dockercfg: $HOME is not defined
> Unable to find image 'descartes:latest' locally
> docker: Error response from daemon: pull access denied for descartes, repository does not exist or may require 'docker login': denied: requested access to the resource is denied.
> See 'docker run --help'.
> Cloud-init v. 20.4.1-0ubuntu1~18.04.1 running 'modules:final' at Wed, 17 Feb 2021 19:59:18 +0000. Up 498.01 seconds.
> 2021-02-17 20:02:16,475 - cc_scripts_user.py[WARNING]: Failed to run module scripts-user (scripts in /var/lib/cloud/instance/scripts)
> 2021-02-17 20:02:16,486 - util.py[WARNING]: Running module scripts-user (<module 'cloudinit.config.cc_scripts_user' from '/usr/lib/python3/dist-packages/cloudinit/config/cc_scripts_user.py'>) failed
> ci-info: no authorized SSH keys fingerprints found for user dask.
> Cloud-init v. 20.4.1-0ubuntu1~18.04.1 finished at Wed, 17 Feb 2021 20:02:16 +0000. Datasource DataSourceAzure [seed=/dev/sr0].  Up 676.60 seconds
> ```

This is exactly the error. The cloud-init thinks that the second variable in the extra_pip is the docker image and it tries to pull it:). I see the very same issue using DropletCluster for Digital Ocean. Could it be the problem in SpecCluster as all of the dask cloud providers instantiate a Dask SpecCluster? I need to do more investigation.
I think the problem lies in dask-cloudprovider/dask_cloudprovider/generic/cloud-init.yaml.j2 file. Line 53 is for run the containers:

`  - 'docker run --net=host {%+ if gpu_instance %}--gpus=all{% endif %} {% for key in env_vars %} -e {{key}}={{env_vars[key]}} {% endfor %}{%+ if docker_args %}{{docker_args}}{% endif %} {{image}} {{ command }}'`

However, this issue happens when we have more than one pip packages in extra_pip_packages of env_vars as we split the packages with a space. This space causes the issue. Obviously, with only having one extra pip package this issue does not appear. 

So, I think instead of `{{key}}={{env_vars[key]}}`, we should have `{{key}}="{{env_vars[key]}}"`. 

> > Coming back to this -- sorry for the delay. Has a security group been defined which allows for 8786 and 8787 to be accessible ?
> > xref: https://cloudprovider.dask.org/en/latest/azure.html#security-groups
> 
> Yes in my case

yeah in my case too
> I think the problem lies in dask-cloudprovider/dask_cloudprovider/generic/cloud-init.yaml.j2 file. Line 53 is for run the containers:
> 
> ` - 'docker run --net=host {%+ if gpu_instance %}--gpus=all{% endif %} {% for key in env_vars %} -e {{key}}={{env_vars[key]}} {% endfor %}{%+ if docker_args %}{{docker_args}}{% endif %} {{image}} {{ command }}'`
> 
> However, this issue happens when we have more than one pip packages in extra_pip_packages of env_vars as we split the packages with a space. This space causes the issue. Obviously, with only having one extra pip package this issue does not appear.
> 
> So, I think instead of `{{key}}={{env_vars[key]}}`, we should have `{{key}}="{{env_vars[key]}}"`.

IT would be great that supporting several env_vars would actually work. In a more general aspect, it would be great if the run would actually fail and throw an error as opposed to just hang 
> @quasiben
> I did try to load the image into an Azure VM I set up manually and it actually failed to load with a "no space left on device" problem.

I tried a different smaller container (rapidsai/rapidsai-core-nightly:0.18-cuda10.2-runtime-ubuntu18.04-py3.8) and that one worked and produced a cluster as expected


> rapidsai/rapidsai-core-nightly:0.18-cuda10.2-runtime-ubuntu18.04-py3.8

what was your extra_pip in this case?

Fix patch:
diff --git a/dask_cloudprovider/generic/cloud-init.yaml.j2 b/dask_cloudprovider/generic/cloud-init.yaml.j2
index df22d1b1..fd1c6fe1 100644
--- a/dask_cloudprovider/generic/cloud-init.yaml.j2
+++ b/dask_cloudprovider/generic/cloud-init.yaml.j2
@@ -50,7 +50,7 @@ runcmd:
   {% endif %}
 
   # Run container
-  - 'docker run --net=host {%+ if gpu_instance %}--gpus=all{% endif %} {% for key in env_vars %} -e {{key}}={{env_vars[key]}} {% endfor %}{%+ if docker_args %}{{docker_args}}{% endif %} {{image}} {{ command }}'
+  - 'docker run --net=host {%+ if gpu_instance %}--gpus=all{% endif %} {% for key in env_vars %} -e {{key}}="{{env_vars[key]}}" {% endfor %}{%+ if docker_args %}{{docker_args}}{% endif %} {{image}} {{ command }}'
 
   {% if auto_shutdown %}
   # Shutdown when command is done


Test patch:
diff --git a/dask_cloudprovider/aws/tests/test_ec2.py b/dask_cloudprovider/aws/tests/test_ec2.py
index e15c3fe2..05b2fa00 100644
--- a/dask_cloudprovider/aws/tests/test_ec2.py
+++ b/dask_cloudprovider/aws/tests/test_ec2.py
@@ -186,7 +186,7 @@ async def test_get_cloud_init():
         docker_args="--privileged",
     )
     assert "systemctl start docker" in cloud_init
-    assert " -e EXTRA_PIP_PACKAGES=s3fs " in cloud_init
+    assert ' -e EXTRA_PIP_PACKAGES="s3fs" ' in cloud_init
     assert " --privileged " in cloud_init