From 2d841631006ddc229483fab4502444452f969785 Mon Sep 17 00:00:00 2001 From: iLLiCiTiT Date: Thu, 15 Oct 2020 15:54:39 +0200 Subject: [PATCH 01/15] change log level of ffmpeg processing --- pype/scripts/otio_burnin.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pype/scripts/otio_burnin.py b/pype/scripts/otio_burnin.py index 6607726c73..123e7cfd1e 100644 --- a/pype/scripts/otio_burnin.py +++ b/pype/scripts/otio_burnin.py @@ -15,7 +15,7 @@ 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 = ( From 6470155aa29836cbaa37fc7fc3baebfd72cd0e5f Mon Sep 17 00:00:00 2001 From: iLLiCiTiT Date: Thu, 15 Oct 2020 15:54:52 +0200 Subject: [PATCH 02/15] formatting changes --- pype/scripts/otio_burnin.py | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/pype/scripts/otio_burnin.py b/pype/scripts/otio_burnin.py index 123e7cfd1e..2ff5f737c9 100644 --- a/pype/scripts/otio_burnin.py +++ b/pype/scripts/otio_burnin.py @@ -308,8 +308,11 @@ class ModifiedBurnins(ffmpeg_burnins.Burnins): % (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): From 06905c880b3927611b29a3c0bcfb0e87b7fe879b Mon Sep 17 00:00:00 2001 From: iLLiCiTiT Date: Thu, 15 Oct 2020 15:55:05 +0200 Subject: [PATCH 03/15] print begin and end of burnin script --- pype/scripts/otio_burnin.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/pype/scripts/otio_burnin.py b/pype/scripts/otio_burnin.py index 2ff5f737c9..040ce5295c 100644 --- a/pype/scripts/otio_burnin.py +++ b/pype/scripts/otio_burnin.py @@ -545,6 +545,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"], @@ -554,3 +555,4 @@ if __name__ == "__main__": options=in_data.get("options"), burnin_values=in_data.get("values") ) + print("* Burnin script has finished") From 3f3dd290831e830778febf40999d5fe09d293f94 Mon Sep 17 00:00:00 2001 From: iLLiCiTiT Date: Thu, 15 Oct 2020 15:57:33 +0200 Subject: [PATCH 04/15] do not use pype Logger in burnin script --- pype/scripts/otio_burnin.py | 10 ++++------ 1 file changed, 4 insertions(+), 6 deletions(-) diff --git a/pype/scripts/otio_burnin.py b/pype/scripts/otio_burnin.py index 040ce5295c..704a08ccbe 100644 --- a/pype/scripts/otio_burnin.py +++ b/pype/scripts/otio_burnin.py @@ -4,11 +4,9 @@ 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") @@ -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,10 +297,10 @@ class ModifiedBurnins(ffmpeg_burnins.Burnins): args=args, overwrite=overwrite ) - log.info("Launching command: {}".format(command)) + print("Launching command: {}".format(command)) proc = subprocess.Popen(command, shell=True) - log.info(proc.communicate()[0]) + print(proc.communicate()[0]) if proc.returncode != 0: raise RuntimeError("Failed to render '%s': %s'" % (output, command)) From d37f4a041f58957b728df17c51d1933a73defbf9 Mon Sep 17 00:00:00 2001 From: iLLiCiTiT Date: Thu, 15 Oct 2020 15:59:10 +0200 Subject: [PATCH 05/15] formatting changes --- pype/scripts/otio_burnin.py | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/pype/scripts/otio_burnin.py b/pype/scripts/otio_burnin.py index 704a08ccbe..5ff8c5a766 100644 --- a/pype/scripts/otio_burnin.py +++ b/pype/scripts/otio_burnin.py @@ -302,8 +302,9 @@ class ModifiedBurnins(ffmpeg_burnins.Burnins): proc = subprocess.Popen(command, shell=True) print(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") From 0709da0fd63b815957be178f988a230e61c08f23 Mon Sep 17 00:00:00 2001 From: iLLiCiTiT Date: Thu, 15 Oct 2020 16:01:16 +0200 Subject: [PATCH 06/15] make sure ffmpeg output is printed out --- pype/scripts/otio_burnin.py | 17 +++++++++++++++-- 1 file changed, 15 insertions(+), 2 deletions(-) diff --git a/pype/scripts/otio_burnin.py b/pype/scripts/otio_burnin.py index 5ff8c5a766..99611b172c 100644 --- a/pype/scripts/otio_burnin.py +++ b/pype/scripts/otio_burnin.py @@ -299,8 +299,21 @@ class ModifiedBurnins(ffmpeg_burnins.Burnins): ) print("Launching command: {}".format(command)) - proc = subprocess.Popen(command, shell=True) - print(proc.communicate()[0]) + 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")) + if proc.returncode != 0: raise RuntimeError( "Failed to render '{}': {}'".format(output, command) From ffa16729dfef1b294f293f9e860bf34c08a56cd6 Mon Sep 17 00:00:00 2001 From: iLLiCiTiT Date: Thu, 15 Oct 2020 16:02:37 +0200 Subject: [PATCH 07/15] formatting in _subprocess --- pype/lib.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/pype/lib.py b/pype/lib.py index 6fa204b379..4f96b14c8a 100644 --- a/pype/lib.py +++ b/pype/lib.py @@ -84,11 +84,11 @@ def get_ffmpeg_tool_path(tool="ffmpeg"): def _subprocess(*args, **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()} + # Get environents from kwarg or use current process environments if were + # not passed. + env = kwargs.get("env") or os.envion + # Make sure environment contains only strings + filtered_env = {k: str(v) for k, v in env.items()} # set overrides kwargs['stdout'] = kwargs.get('stdout', subprocess.PIPE) From 63b7a2a24458edca21b69b2adbc6d63164809dc1 Mon Sep 17 00:00:00 2001 From: iLLiCiTiT Date: Thu, 15 Oct 2020 16:03:20 +0200 Subject: [PATCH 08/15] allow to pass logger to _subprocess --- pype/lib.py | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/pype/lib.py b/pype/lib.py index 4f96b14c8a..8a12e33e63 100644 --- a/pype/lib.py +++ b/pype/lib.py @@ -81,8 +81,7 @@ 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): # Get environents from kwarg or use current process environments if were # not passed. @@ -90,6 +89,10 @@ def _subprocess(*args, **kwargs): # 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) From dca6d0db27a5b1e5d202d4a49db760e6b01d333e Mon Sep 17 00:00:00 2001 From: iLLiCiTiT Date: Thu, 15 Oct 2020 16:03:51 +0200 Subject: [PATCH 09/15] stderr use PIPE instead of STDOUT --- pype/lib.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pype/lib.py b/pype/lib.py index 8a12e33e63..0f19a68ae6 100644 --- a/pype/lib.py +++ b/pype/lib.py @@ -95,7 +95,7 @@ def _subprocess(*args, logger=None, **kwargs): # 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 From 891829a4abd145bc5b0a5df36546b7458f083c8c Mon Sep 17 00:00:00 2001 From: iLLiCiTiT Date: Thu, 15 Oct 2020 16:05:15 +0200 Subject: [PATCH 10/15] stdout and stderr are logged at once to logger --- pype/lib.py | 19 +++++++------------ 1 file changed, 7 insertions(+), 12 deletions(-) diff --git a/pype/lib.py b/pype/lib.py index 0f19a68ae6..978386af3a 100644 --- a/pype/lib.py +++ b/pype/lib.py @@ -101,19 +101,14 @@ def _subprocess(*args, logger=None, **kwargs): proc = subprocess.Popen(*args, **kwargs) - output, error = proc.communicate() + _stdout, _stderr = proc.communicate() + if _stdout: + _stdout = _stdout.decode("utf-8") + 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") + logger.warning(_stderr) if proc.returncode != 0: raise ValueError( From f5707a48e4b11fcedf505bc119959cfcdf66c9e4 Mon Sep 17 00:00:00 2001 From: iLLiCiTiT Date: Thu, 15 Oct 2020 16:06:00 +0200 Subject: [PATCH 11/15] _subprocess is returning full output with stderr and stdout --- pype/lib.py | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/pype/lib.py b/pype/lib.py index 978386af3a..5fb9091cc1 100644 --- a/pype/lib.py +++ b/pype/lib.py @@ -101,20 +101,26 @@ def _subprocess(*args, logger=None, **kwargs): proc = subprocess.Popen(*args, **kwargs) + full_output = "" _stdout, _stderr = proc.communicate() if _stdout: _stdout = _stdout.decode("utf-8") + full_output += _stdout logger.debug(_stdout) 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 + return full_output def get_hierarchy(asset_name=None): From ae905c0e5768bb040f80d9afe4f1a6224fa2b641 Mon Sep 17 00:00:00 2001 From: iLLiCiTiT Date: Thu, 15 Oct 2020 16:06:21 +0200 Subject: [PATCH 12/15] raise Runtime error with stdout ann stderr --- pype/lib.py | 12 +++++++++--- 1 file changed, 9 insertions(+), 3 deletions(-) diff --git a/pype/lib.py b/pype/lib.py index 5fb9091cc1..9b21878701 100644 --- a/pype/lib.py +++ b/pype/lib.py @@ -117,9 +117,15 @@ def _subprocess(*args, logger=None, **kwargs): logger.warning(_stderr) if proc.returncode != 0: - raise ValueError( - "\"{}\" was not successful:\nOutput: {}\nError: {}".format( - args, output, error)) + 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 From cb2ca581e1a5fe55e342d42b6c3da5792c01ab26 Mon Sep 17 00:00:00 2001 From: iLLiCiTiT Date: Thu, 15 Oct 2020 16:06:28 +0200 Subject: [PATCH 13/15] added docstring --- pype/lib.py | 17 +++++++++++++++++ 1 file changed, 17 insertions(+) diff --git a/pype/lib.py b/pype/lib.py index 9b21878701..ff9571de77 100644 --- a/pype/lib.py +++ b/pype/lib.py @@ -82,6 +82,23 @@ def get_ffmpeg_tool_path(tool="ffmpeg"): # Special naming case for subprocess since its a built-in method. def _subprocess(*args, logger=None, **kwargs): + """Convenience method for getting output errors for subprocess. + + 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. From 4113c072812a5cc8b8eaf8b436820d3620020cad Mon Sep 17 00:00:00 2001 From: iLLiCiTiT Date: Thu, 15 Oct 2020 16:07:12 +0200 Subject: [PATCH 14/15] extract review and extract burnin are passing logger to _subprocess --- pype/plugins/global/publish/extract_burnin.py | 3 +-- pype/plugins/global/publish/extract_review.py | 6 ++++-- 2 files changed, 5 insertions(+), 4 deletions(-) diff --git a/pype/plugins/global/publish/extract_burnin.py b/pype/plugins/global/publish/extract_burnin.py index 353f2f27f0..6a164fd1f0 100644 --- a/pype/plugins/global/publish/extract_burnin.py +++ b/pype/plugins/global/publish/extract_burnin.py @@ -229,8 +229,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("\\", "/") diff --git a/pype/plugins/global/publish/extract_review.py b/pype/plugins/global/publish/extract_review.py index f4a39a7c31..0a3077ca4f 100644 --- a/pype/plugins/global/publish/extract_review.py +++ b/pype/plugins/global/publish/extract_review.py @@ -180,8 +180,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"]: From 9880488255e134cacf208b0f20bf41f06bb3c364 Mon Sep 17 00:00:00 2001 From: iLLiCiTiT Date: Fri, 16 Oct 2020 10:49:42 +0200 Subject: [PATCH 15/15] fixed typo --- pype/lib.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pype/lib.py b/pype/lib.py index ff9571de77..f364945a86 100644 --- a/pype/lib.py +++ b/pype/lib.py @@ -102,7 +102,7 @@ def _subprocess(*args, logger=None, **kwargs): # Get environents from kwarg or use current process environments if were # not passed. - env = kwargs.get("env") or os.envion + env = kwargs.get("env") or os.environ # Make sure environment contains only strings filtered_env = {k: str(v) for k, v in env.items()}