Log output while Popen is in progress (#45)

* Parallel logging and execute command

Currently the `execute_command` function will only log the output after the command has completed, considering that the resources being created may take a long time, getting feedback during execution would be very valuable.

* fixed tabbing

* fixed  another tab tab

* Update tftest.py

* revised based on comments
- fixed formatting
- used list instead of string concat
- add encoding and ignore error params to popen

Co-authored-by: Ludovico Magnocavallo <[email protected]>

test/test_plan.py

@@ -80,3 +80,9 @@ def test_plan_with_no_resources_succeeds(fixtures_dir):
   result = tf.plan(output=True)
 
   assert result.outputs['just_an_output'] == 'Hello, plan!'
+
+
+def test_plan_stdout(fixtures_dir):
+  tf = tftest.TerraformTest('plan_no_resource_changes', fixtures_dir)
+  result = tf.plan(output=False)
+  assert 'just_an_output = "Hello, plan!"' in result

tftest.py

@@ -102,7 +102,8 @@ def parse_args(init_vars=None, tf_vars=None, targets=None, **kw):
                for arg in _TG_BOOL_ARGS if kw.get(f"tg_{arg}")]
   for arg in _TG_KV_ARGS:
     if kw.get(f"tg_{arg}"):
-      cmd_args += [f'--terragrunt-{arg.replace("_", "-")}', kw[f"tg_{arg}"]]
+      cmd_args += [f'--terragrunt-{arg.replace("_", "-")}',
+                   kw[f"tg_{arg}"]]
   if kw.get('tg_parallelism'):
     cmd_args.append(f'--terragrunt-parallelism {kw["tg_parallelism"]}')
   if isinstance(kw.get('tg_override_attr'), dict):
@@ -296,7 +297,8 @@ def __init__(self, tfdir, basedir=None, binary='terraform', env=None):
     self.env = os.environ.copy()
     self.tg_run_all = False
     self._plan_formatter = lambda out: TerraformPlanOutput(json.loads(out))
-    self._output_formatter = lambda out: TerraformValueDict(json.loads(out))
+    self._output_formatter = lambda out: TerraformValueDict(
+        json.loads(out))
     if env is not None:
       self.env.update(env)
 
@@ -324,11 +326,13 @@ def remove_readonly(func, path, excinfo):
     for tg_dir in glob.glob(path, recursive=True):
       if os.path.isdir(tg_dir):
         shutil.rmtree(tg_dir, onerror=remove_readonly)
-    _LOGGER.debug('Restoring original TF files after prevent destroy changes')
+    _LOGGER.debug(
+        'Restoring original TF files after prevent destroy changes')
     if restore_files:
       for bkp_file in Path(tfdir).rglob('*.bkp'):
         try:
-          shutil.copy(str(bkp_file), f'{str(bkp_file).strip(".bkp")}')
+          shutil.copy(str(bkp_file),
+                      f'{str(bkp_file).strip(".bkp")}')
         except (IOError, OSError):
           _LOGGER.exception(
               f'Unable to restore terraform file {bkp_file.resolve()}')
@@ -378,8 +382,9 @@ def setup(self, extra_files=None, plugin_dir=None, init_vars=None,
           with open(tf_file, 'r') as src:
             terraform = src.read()
           with open(tf_file, 'w') as src:
-            terraform = re.sub(r'prevent_destroy\s+=\s+true',
-                               'prevent_destroy = false', terraform)
+
+            terraform = re.sub(
+                r'prevent_destroy\s+=\s+true', 'prevent_destroy = false', terraform)
             src.write(terraform)
         except (OSError, IOError):
           _LOGGER.exception(
@@ -450,7 +455,8 @@ def plan(self, input=False, color=False, refresh=True, tf_vars=None,
     try:
       return self._plan_formatter(result.out)
     except json.JSONDecodeError as e:
-      raise TerraformTestError('Error decoding plan output: {}'.format(e))
+      raise TerraformTestError(
+          'Error decoding plan output: {}'.format(e))
 
   def apply(self, input=False, color=False, auto_approve=True,
             tf_vars=None, targets=None, tf_var_file=None, **kw):
@@ -514,21 +520,37 @@ def execute_command(self, cmd, *cmd_args):
     cmdline = [self.binary, *self._tg_ra(), cmd]
     cmdline += cmd_args
     _LOGGER.info(cmdline)
+    retcode = None
+    full_output_lines = []
     try:
-      p = subprocess.Popen(cmdline, stdout=subprocess.PIPE,
-                           stderr=subprocess.PIPE, cwd=self.tfdir, env=self.env)
+      p = subprocess.Popen(cmdline,
+                           stdout=subprocess.PIPE,
+                           stderr=subprocess.PIPE,
+                           cwd=self.tfdir,
+                           env=self.env,
+                           universal_newlines=True,
+                           encoding='utf-8',
+                           errors='ignore')
+      while True:
+        output = p.stdout.readline()
+        if output == '' and p.poll() is not None:
+          break
+        if output:
+          _LOGGER.info(output.strip())
+          full_output_lines.append(output)
+      retcode = p.poll()
+      p.stdout.close()
+      p.wait()
     except FileNotFoundError as e:
       raise TerraformTestError('Terraform executable not found: %s' % e)
     out, err = p.communicate()
-    out = out.decode('utf-8', errors='ignore')
-    err = err.decode('utf-8', errors='ignore')
-    retcode = p.returncode
+    full_output = "".join(full_output_lines)
     if retcode == 1:
       message = 'Error running command {command}: {retcode} {out} {err}'.format(
-          command=cmd, retcode=retcode, out=out, err=err)
+          command=cmd, retcode=retcode, out=full_output, err=err)
       _LOGGER.critical(message)
       raise TerraformTestError(message)
-    return TerraformCommandOutput(retcode, out, err)
+    return TerraformCommandOutput(retcode, full_output, err)
 
   def _tg_ra(self) -> List[str]:
     """if run_all return ['run-all'] else [] """