fix: accurately log shell commands when running jobs

Whenever Tutor executes a shell command, it logs out said
command in order to aid in end user understanding/debugging.

In some cases (notably, when running jobs in containers)
the logged command was not accurately quoted. The command
was run correctly, because it was passed in pieces to
``subprocess.Popen``, which correctly joins the pieces together
into a valid POSIX shell command; however, the logged version
of the command was constructed by simply joining the pieces
with spaces. This usually works, but breaks down when running
complex shell commands with nested quoting.

This commit changes the logging to use ``shlex.join``, which
joins command pieces together in a POSIX-compliant way,
presumably the same way as ``subprocess.Popen``.

Example:

    tutor local importdemocourse

runs the shell command:

    docker-compose -f /home/kyle/.local/share/tutor/env/local/docker-compose.yml -f /home/kyle/.local/share/tutor/env/local/docker-compose.prod.yml -f /home/kyle/.local/share/tutor/env/local/docker-compose.tmp.yml --project-name tutor_local -f /home/kyle/.local/share/tutor/env/local/docker-compose.jobs.yml -f /home/kyle/.local/share/tutor/env/local/docker-compose.jobs.tmp.yml run --rm cms-job sh -e -c 'echo "Loading settings $DJANGO_SE... (several more script lines) ...eindex_course --all --setup'

but the logged shell command was:

    docker-compose -f /home/kyle/.local/share/tutor/env/local/docker-compose.yml -f /home/kyle/.local/share/tutor/env/local/docker-compose.prod.yml -f /home/kyle/.local/share/tutor/env/local/docker-compose.tmp.yml --project-name tutor_local -f /home/kyle/.local/share/tutor/env/local/docker-compose.jobs.yml -f /home/kyle/.local/share/tutor/env/local/docker-compose.jobs.tmp.yml run --rm cms-job sh -e -c echo "Loading settings $DJANGO_SE... (several more script lines) ...eindex_course --all --setup

which will not run if copied and pasted back into the
user's terminal, as the importdemocourse shell script is unquoted.

CHANGELOG.md

@@ -18,6 +18,7 @@ Every user-facing change should have an entry in this changelog. Please respect
 
 ## Unreleased
 
+- [Bugfix] Log the shell commands that Tutor executes more accurately. (by @kdmccormick)
 - [Fix] `tutor dev quickstart` would fail under certain versions of docker-compose due to a bug in the logic that handled volume mounting. (by @kdmccormick)
 - [Bugfix] The `tutor k8s start` command will succeed even when `k8s-override` and `kustomization-patches-strategic-merge` are not specified. (by @edazzocaisser)
 - [Fix] `kubectl wait` checks deployments instead of pods as it could hang indefinitely if there are extra pods in a broken state. (by @keithgg)

tests/test_utils.py

@@ -102,7 +102,23 @@ class UtilsTests(unittest.TestCase):
 
         result = utils.execute("echo", "")
         self.assertEqual(0, result)
-        self.assertEqual("echo \n", mock_stdout.getvalue())
+        self.assertEqual("echo ''\n", mock_stdout.getvalue())
+        self.assertEqual(1, process.wait.call_count)
+        process.kill.assert_not_called()
+
+    @patch("sys.stdout", new_callable=StringIO)
+    @patch("subprocess.Popen", autospec=True)
+    def test_execute_nested_command(
+        self, mock_popen: MagicMock, mock_stdout: StringIO
+    ) -> None:
+        process = mock_popen.return_value
+        mock_popen.return_value.__enter__.return_value = process
+        process.wait.return_value = 0
+        process.communicate.return_value = ("output", "error")
+
+        result = utils.execute("bash", "-c", "echo -n hi")
+        self.assertEqual(0, result)
+        self.assertEqual("bash -c 'echo -n hi'\n", mock_stdout.getvalue())
         self.assertEqual(1, process.wait.call_count)
         process.kill.assert_not_called()
 
@@ -117,7 +133,7 @@ class UtilsTests(unittest.TestCase):
         process.communicate.return_value = ("output", "error")
 
         self.assertRaises(exceptions.TutorError, utils.execute, "echo", "")
-        self.assertEqual("echo \n", mock_stdout.getvalue())
+        self.assertEqual("echo ''\n", mock_stdout.getvalue())
         self.assertEqual(1, process.wait.call_count)
         process.kill.assert_not_called()
 
@@ -131,7 +147,7 @@ class UtilsTests(unittest.TestCase):
         process.wait.side_effect = ZeroDivisionError("Exception occurred.")
 
         self.assertRaises(ZeroDivisionError, utils.execute, "echo", "")
-        self.assertEqual("echo \n", mock_stdout.getvalue())
+        self.assertEqual("echo ''\n", mock_stdout.getvalue())
         self.assertEqual(2, process.wait.call_count)
         process.kill.assert_called_once()
 

tutor/utils.py

@@ -3,6 +3,7 @@ from functools import lru_cache
 import json
 import os
 import random
+import shlex
 import shutil
 import string
 import struct
@@ -201,7 +202,7 @@ def is_a_tty() -> bool:
 
 
 def execute(*command: str) -> int:
-    click.echo(fmt.command(" ".join(command)))
+    click.echo(fmt.command(shlex.join(command)))
     with subprocess.Popen(command) as p:
         try:
             result = p.wait(timeout=None)