Merge pull request #641 from pypeclub/feature/burnin_script_output

Burnin script logs better output

pype/lib.py

@@ -81,42 +81,69 @@ def get_ffmpeg_tool_path(tool="ffmpeg"):
 
 
 # Special naming case for subprocess since its a built-in method.
-def _subprocess(*args, **kwargs):
-    """Convenience method for getting output errors for subprocess."""
+def _subprocess(*args, logger=None, **kwargs):
+    """Convenience method for getting output errors for subprocess.
 
-    # make sure environment contains only strings
-    if not kwargs.get("env"):
-        filtered_env = {k: str(v) for k, v in os.environ.items()}
-    else:
-        filtered_env = {k: str(v) for k, v in kwargs.get("env").items()}
+    Entered arguments and keyword arguments are passed to subprocess Popen.
+
+    Args:
+        logger (logging.Logger): Logger object if want to use different than
+            lib's logger.
+        *args: Variable length arument list passed to Popen.
+        **kwargs : Arbitary keyword arguments passed to Popen.
+
+    Returns:
+        str: Full output of subprocess concatenated stdout and stderr.
+
+    Raises:
+        RuntimeError: Exception is raised if process finished with nonzero
+            return code.
+    """
+
+    # Get environents from kwarg or use current process environments if were
+    # not passed.
+    env = kwargs.get("env") or os.environ
+    # Make sure environment contains only strings
+    filtered_env = {k: str(v) for k, v in env.items()}
+
+    # Use lib's logger if was not passed with kwargs.
+    if not logger:
+        logger = log
 
     # set overrides
     kwargs['stdout'] = kwargs.get('stdout', subprocess.PIPE)
-    kwargs['stderr'] = kwargs.get('stderr', subprocess.STDOUT)
+    kwargs['stderr'] = kwargs.get('stderr', subprocess.PIPE)
     kwargs['stdin'] = kwargs.get('stdin', subprocess.PIPE)
     kwargs['env'] = filtered_env
 
     proc = subprocess.Popen(*args, **kwargs)
 
-    output, error = proc.communicate()
+    full_output = ""
+    _stdout, _stderr = proc.communicate()
+    if _stdout:
+        _stdout = _stdout.decode("utf-8")
+        full_output += _stdout
+        logger.debug(_stdout)
 
-    if output:
-        output = output.decode("utf-8")
-        output += "\n"
-        for line in output.strip().split("\n"):
-            log.info(line)
-
-    if error:
-        error = error.decode("utf-8")
-        error += "\n"
-        for line in error.strip().split("\n"):
-            log.error(line)
+    if _stderr:
+        _stderr = _stderr.decode("utf-8")
+        # Add additional line break if output already containt stdout
+        if full_output:
+            full_output += "\n"
+        full_output += _stderr
+        logger.warning(_stderr)
 
     if proc.returncode != 0:
-        raise ValueError(
-            "\"{}\" was not successful:\nOutput: {}\nError: {}".format(
-                args, output, error))
-    return output
+        exc_msg = "Executing arguments was not successful: \"{}\"".format(args)
+        if _stdout:
+            exc_msg += "\n\nOutput:\n{}".format(_stdout)
+
+        if _stderr:
+            exc_msg += "Error:\n{}".format(_stderr)
+
+        raise RuntimeError(exc_msg)
+
+    return full_output
 
 
 def get_hierarchy(asset_name=None):

pype/plugins/global/publish/extract_burnin.py

@@ -227,8 +227,7 @@ class ExtractBurnin(pype.api.Extractor):
                 self.log.debug("Executing: {}".format(args))
 
                 # Run burnin script
-                output = pype.api.subprocess(args, shell=True)
-                self.log.debug("Output: {}".format(output))
+                pype.api.subprocess(args, shell=True, logger=self.log)
 
                 for filepath in temp_data["full_input_paths"]:
                     filepath = filepath.replace("\\", "/")

pype/plugins/global/publish/extract_review.py

@@ -181,8 +181,10 @@ class ExtractReview(pyblish.api.InstancePlugin):
 
                 # run subprocess
                 self.log.debug("Executing: {}".format(subprcs_cmd))
-                output = pype.api.subprocess(subprcs_cmd, shell=True)
-                self.log.debug("Output: {}".format(output))
+
+                pype.api.subprocess(
+                    subprcs_cmd, shell=True, logger=self.log
+                )
 
                 output_name = output_def["filename_suffix"]
                 if temp_data["without_handles"]:

pype/scripts/otio_burnin.py

@@ -4,18 +4,16 @@ import re
 import subprocess
 import json
 import opentimelineio_contrib.adapters.ffmpeg_burnins as ffmpeg_burnins
-from pype.api import Logger, config
+from pype.api import config
 import pype.lib
 
-log = Logger().get_logger("BurninWrapper", "burninwrap")
-
 
 ffmpeg_path = pype.lib.get_ffmpeg_tool_path("ffmpeg")
 ffprobe_path = pype.lib.get_ffmpeg_tool_path("ffprobe")
 
 
 FFMPEG = (
-    '{} -loglevel panic -i "%(input)s" %(filters)s %(args)s%(output)s'
+    '{} -i "%(input)s" %(filters)s %(args)s%(output)s'
 ).format(ffmpeg_path)
 
 FFPROBE = (
@@ -54,7 +52,7 @@ def _streams(source):
 
 def get_fps(str_value):
     if str_value == "0/0":
-        log.warning("Source has \"r_frame_rate\" value set to \"0/0\".")
+        print("WARNING: Source has \"r_frame_rate\" value set to \"0/0\".")
         return "Unknown"
 
     items = str_value.split("/")
@@ -299,17 +297,34 @@ class ModifiedBurnins(ffmpeg_burnins.Burnins):
             args=args,
             overwrite=overwrite
         )
-        log.info("Launching command: {}".format(command))
+        print("Launching command: {}".format(command))
+
+        proc = subprocess.Popen(
+            command,
+            stdout=subprocess.PIPE,
+            stderr=subprocess.PIPE,
+            shell=True
+        )
+
+        _stdout, _stderr = proc.communicate()
+        if _stdout:
+            print(_stdout.decode("utf-8"))
+
+        # This will probably never happen as ffmpeg use stdout
+        if _stderr:
+            print(_stderr.decode("utf-8"))
 
-        proc = subprocess.Popen(command, shell=True)
-        log.info(proc.communicate()[0])
         if proc.returncode != 0:
-            raise RuntimeError("Failed to render '%s': %s'"
-                               % (output, command))
+            raise RuntimeError(
+                "Failed to render '{}': {}'".format(output, command)
+            )
         if is_sequence:
             output = output % kwargs.get("duration")
+
         if not os.path.exists(output):
-            raise RuntimeError("Failed to generate this fucking file '%s'" % output)
+            raise RuntimeError(
+                "Failed to generate this f*cking file '%s'" % output
+            )
 
 
 def example(input_path, output_path):
@@ -542,6 +557,7 @@ def burnins_from_data(
 
 
 if __name__ == "__main__":
+    print("* Burnin script started")
     in_data = json.loads(sys.argv[-1])
     burnins_from_data(
         in_data["input"],
@@ -551,3 +567,4 @@ if __name__ == "__main__":
         options=in_data.get("options"),
         burnin_values=in_data.get("values")
     )
+    print("* Burnin script has finished")