Trying to run globusconnectpersonal 3.2.0 setup (under a complex scenario) fails under mysterious circumstances

[Nicholas Mei]

Hi all,

I'm encountering a strange failure when trying to setup globusconnectpersonal (3.2.0) with a `--setup-key` under somewhat complex circumstances. Here are relevant details:

1. The setup command is run via Python (3.8) subprocess with a command that looks like:

```

import subprocess as sp

result = sp.run( ['/opt/globusconnectpersonal/globusconnectpersonal', '-setup', '--debug', '--setup-key', f'{setup_key_that_was_obtained_via_globus_sdk}'], shell=False, capture_output=True)

```

2. The python code is in turn run within a docker container whose dockerfile looks something like: https://gist.github.com/njmei/ab3dadbfb2f821eceb7ec43e1f2af85a

This can be run successfully with something like:

> docker build -t test-globusconnectpersonal-setup-image .

> docker run -it --rm -e GLOBUS_SETUP_KEY=${YOUR_GLOBUS_SETUP_KEY} test-globusconnectpersonal-setup-image

3. To add to the complexity, this Dockerfile is run on an EC2 instance via AWS Batch.

- I've confirmed that there does not appear to be any problems with network settings (VPCs, Security Groups, etc...) as I can run `telnet relay.globusonline.org 2223` when I `docker exec` into the running container on the EC2 instance and get no problems.

Anyways, here is the detailed debug logs that are emitted:

[DEBUG] cli.py::52 [_setup_logging] logging setup done. logfile=/home/data_transfer_user/.globusonline/lta/register.log\n

[INFO] cli.py::190 [main] got --setup-key, skip endpoint creation...\n

[INFO] cli.py::196 [main] starting relaytool setup\n

[DEBUG] relaytool.py::37 [_get_etc_dir] checking if dir(/opt/globusconnectpersonal/gt_amd64/bin/etc) exists\n

[DEBUG] relaytool.py::37 [_get_etc_dir] checking if dir(/opt/globusconnectpersonal/gt_amd64/etc) exists\n

[DEBUG] relaytool.py::37 [_get_etc_dir] checking if dir(/opt/globusconnectpersonal/etc) exists\n

[DEBUG] relaytool.py::109 [setup_relaytool_environment] env setup done; installing GCP to GCP_CONFIG_DIR=/home/data_transfer_user/.globusonline/lta\n

[WARNING] relaytool.py::136 [invoke_relaytool] relaytool setup exit with status 1, indicating failure. use debug mode for full output\n

[DEBUG] relaytool.py::140 [invoke_relaytool] relaytool stdout:\n-----\n\n-----\n

[DEBUG] relaytool.py::144 [invoke_relaytool] relaytool stderr:\n-----\n\n-----\n

[INFO] cli.py::200 [main] relaytool stdout:\n-----\n(\'\',)-----\n

[INFO] cli.py::201 [main] relaytool stderr:\n-----\n(\'\',)\n-----\n

[INFO] cli.py::202 [main] full trace of relaytool failure\nTraceback (most recent call last):\n File "lib/cli.py", line 198, in main\n File "lib/relaytool.py", line 151, in run_relaytool_setup\n File "lib/relaytool.py", line 146, in invoke_relaytool\nlib.relaytool.RelayToolFailureError: (\'relaytool setup failed\', CompletedProcess(args=\'/opt/globusconnectpersonal/gt_amd64/bin/relaytool\', returncode=1, stdout=b\'\', stderr=b\'\'))\n

[ERROR] cli.py::203 [main] relaytool failed, full error info available in register.log\nPyInstaller/loader/pyimod03_importers.py:495: CryptographyDeprecationWarning: Python 3.6 is no longer supported by the Python core team. Therefore, support for it is deprecated in cryptography and will be removed in a future release.\n\n Setup did not complete successfully.\nYou may want to check /home/data_transfer_user/.globusonline/lta/register.log for more information\n'

Unfortunately the log messages are extremely unhelpful especially the call to the `relaytool` which returns:

CompletedProcess(args=\'/opt/globusconnectpersonal/gt_amd64/bin/relaytool\', returncode=1, stdout=b\'\', stderr=b\'\'))

Is there anywhere that I could see the source of the relaytool to try to get a bit more insight into what is going wrong? Any assistance would be greatly appreciated!!

Best,

Nick

[Michael Link]

Hi Nick,

I've seen something like this when trying to run setup in a detached
process, as relaytool checks for a valid stdin. You can set the
environment variable GCP_DEBUG=1 to get additional output from relaytool.

Mike

[Nicholas Mei]

Hi Mike,

Many thanks for the super helpful reply. It doesn't look like the `GCP_DEBUG=1` environment variable flag is documented anywhere on the globusconnectpersonal help pages that I searched through.

As you had suspected the `ssh` command that the relaytool was calling was expecting an open stdin PIPE:

    [relaytool debug] pid=48 SSH queueing stdin: [msg=SETUP_C code={REDACTED} appver=3.1.2 ostype=linux osver=Ubuntu-20.04\\\\n]\\n
    [relaytool debug] pid=48 poll: ret=2\\n
    [relaytool debug] pid=48 processing fd 0\\n
    [relaytool debug] pid=48 stdin closed; parent died?\\n

For posterity, changing the subprocess call to this appears to resolve the issue:

```

        # NOTE: The globusconnectpersonal -setup command REQUIRES an open and active stdin.
        #       So our strategy will be to open a stdin=subprocess.PIPE, sleep and wait for the
        #       setup command until it no longer needs an active stdin, and then call
        #       process.communicate() to obtain stdout, stderr and automatically close stdin.

        # NOTE 2: If globusconnectpersonal -setup fails in the future you can set
        #         `env={"GCP_DEBUG": "1"}`, which will provide detailed debug details
        #         from the register/relaytool executables that the globusconnectpersonal bash
        #         script calls.

        # See: http://pymotw.com/2/subprocess/index.html#process-groups-sessions for
        #      rationale behind preexec_fn=os.setsid.
        process = subprocess.Popen(
            globusconnectpersonal_setup_cmd,
            shell=False,
            preexec_fn=os.setsid,
            stdin=subprocess.PIPE,
            stdout=subprocess.PIPE,
            stderr=subprocess.PIPE
        )
        time.sleep(30)
        process_stdout, process_stderr = process.communicate()
        return_code = process.wait()

```

Best,

Nick