Enhancement: Improve logging levels and messages for artist facing publish reports (#5018)

* Tweak log levels and message to be more informative to artist in report page

* Tweak levels and clarity of logs

* Tweak levels and clarity of logs + tweak grammar

* Cosmetics

* Improve logging

* Simplify logging

* Convert to debug log if it's skipping thumbnail integration if there's no thumbnail whatsoever to integrate

* Tweak to debug since they only show representation ids hardly understandable to the artist

* Match logging message across hosts + include filepath for full clarity

* Tweak message to clarify it only starts checking and not that it requires filling + to debug log

* Tweak to debug log if there's basically no thumbnail to integrate at the end

* Tweak log levels

- Artist doesn't care what's prepared, especially since afterwards it's logged what gets written to the database anyway

* Log clearly it's processing a legacy instance

* Cosmetics

openpype/hosts/fusion/plugins/publish/collect_inputs.py

@@ -113,4 +113,4 @@ class CollectUpstreamInputs(pyblish.api.InstancePlugin):
 
         inputs = [c["representation"] for c in containers]
         instance.data["inputRepresentations"] = inputs
-        self.log.info("Collected inputs: %s" % inputs)
+        self.log.debug("Collected inputs: %s" % inputs)

openpype/hosts/fusion/plugins/publish/save_scene.py

@@ -17,5 +17,5 @@ class FusionSaveComp(pyblish.api.ContextPlugin):
         current = comp.GetAttrs().get("COMPS_FileName", "")
         assert context.data['currentFile'] == current
 
-        self.log.info("Saving current file..")
+        self.log.info("Saving current file: {}".format(current))
         comp.Save()

openpype/hosts/houdini/plugins/publish/collect_frames.py

@@ -8,7 +8,6 @@ import pyblish.api
 from openpype.hosts.houdini.api import lib
 
 
-
 class CollectFrames(pyblish.api.InstancePlugin):
     """Collect all frames which would be saved from the ROP nodes"""
 
@@ -34,8 +33,10 @@ class CollectFrames(pyblish.api.InstancePlugin):
             self.log.warning("Using current frame: {}".format(hou.frame()))
             output = output_parm.eval()
 
-        _, ext = lib.splitext(output,
-                          allowed_multidot_extensions=[".ass.gz"])
+        _, ext = lib.splitext(
+            output,
+            allowed_multidot_extensions=[".ass.gz"]
+        )
         file_name = os.path.basename(output)
         result = file_name
 

openpype/hosts/houdini/plugins/publish/collect_inputs.py

@@ -117,4 +117,4 @@ class CollectUpstreamInputs(pyblish.api.InstancePlugin):
 
         inputs = [c["representation"] for c in containers]
         instance.data["inputRepresentations"] = inputs
-        self.log.info("Collected inputs: %s" % inputs)
+        self.log.debug("Collected inputs: %s" % inputs)

openpype/hosts/houdini/plugins/publish/collect_instances.py

@@ -55,7 +55,9 @@ class CollectInstances(pyblish.api.ContextPlugin):
             has_family = node.evalParm("family")
             assert has_family, "'%s' is missing 'family'" % node.name()
 
-            self.log.info("processing {}".format(node))
+            self.log.info(
+                "Processing legacy instance node {}".format(node.path())
+            )
 
             data = lib.read(node)
             # Check bypass state and reverse

openpype/hosts/houdini/plugins/publish/collect_workfile.py

@@ -32,5 +32,4 @@ class CollectWorkfile(pyblish.api.InstancePlugin):
             "stagingDir": folder,
         }]
 
-        self.log.info('Collected instance: {}'.format(file))
-        self.log.info('staging Dir: {}'.format(folder))
+        self.log.debug('Collected workfile instance: {}'.format(file))

openpype/hosts/houdini/plugins/publish/save_scene.py

@@ -20,7 +20,7 @@ class SaveCurrentScene(pyblish.api.ContextPlugin):
         )
 
         if host.has_unsaved_changes():
-            self.log.info("Saving current file {}...".format(current_file))
+            self.log.info("Saving current file: {}".format(current_file))
             host.save_workfile(current_file)
         else:
             self.log.debug("No unsaved changes, skipping file save..")

openpype/hosts/houdini/plugins/publish/validate_workfile_paths.py

@@ -28,18 +28,37 @@ class ValidateWorkfilePaths(
         if not self.is_active(instance.data):
             return
         invalid = self.get_invalid()
-        self.log.info(
-            "node types to check: {}".format(", ".join(self.node_types)))
-        self.log.info(
-            "prohibited vars: {}".format(", ".join(self.prohibited_vars))
+        self.log.debug(
+            "Checking node types: {}".format(", ".join(self.node_types)))
+        self.log.debug(
+            "Searching prohibited vars: {}".format(
+                ", ".join(self.prohibited_vars)
+            )
         )
-        if invalid:
-            for param in invalid:
-                self.log.error(
-                    "{}: {}".format(param.path(), param.unexpandedString()))
 
-            raise PublishValidationError(
-                "Invalid paths found", title=self.label)
+        if invalid:
+            all_container_vars = set()
+            for param in invalid:
+                value = param.unexpandedString()
+                contained_vars = [
+                    var for var in self.prohibited_vars
+                    if var in value
+                ]
+                all_container_vars.update(contained_vars)
+
+                self.log.error(
+                    "Parm {} contains prohibited vars {}: {}".format(
+                        param.path(),
+                        ", ".join(contained_vars),
+                        value)
+                )
+
+            message = (
+                "Prohibited vars {} found in parameter values".format(
+                    ", ".join(all_container_vars)
+                )
+            )
+            raise PublishValidationError(message, title=self.label)
 
     @classmethod
     def get_invalid(cls):
@@ -63,7 +82,7 @@ class ValidateWorkfilePaths(
     def repair(cls, instance):
         invalid = cls.get_invalid()
         for param in invalid:
-            cls.log.info("processing: {}".format(param.path()))
+            cls.log.info("Processing: {}".format(param.path()))
             cls.log.info("Replacing {} for {}".format(
                 param.unexpandedString(),
                 hou.text.expandString(param.unexpandedString())))

openpype/hosts/maya/plugins/publish/collect_inputs.py

@@ -166,7 +166,7 @@ class CollectUpstreamInputs(pyblish.api.InstancePlugin):
 
         inputs = [c["representation"] for c in containers]
         instance.data["inputRepresentations"] = inputs
-        self.log.info("Collected inputs: %s" % inputs)
+        self.log.debug("Collected inputs: %s" % inputs)
 
     def _collect_renderlayer_inputs(self, scene_containers, instance):
         """Collects inputs from nodes in renderlayer, incl. shaders + camera"""

openpype/hosts/maya/plugins/publish/save_scene.py

@@ -31,5 +31,5 @@ class SaveCurrentScene(pyblish.api.ContextPlugin):
         # remove lockfile before saving
         if is_workfile_lock_enabled("maya", project_name, project_settings):
             remove_workfile_lock(current)
-        self.log.info("Saving current file..")
+        self.log.info("Saving current file: {}".format(current))
         cmds.file(save=True, force=True)

openpype/hosts/substancepainter/plugins/publish/save_workfile.py

@@ -16,11 +16,12 @@ class SaveCurrentWorkfile(pyblish.api.ContextPlugin):
     def process(self, context):
 
         host = registered_host()
-        if context.data["currentFile"] != host.get_current_workfile():
+        current = host.get_current_workfile()
+        if context.data["currentFile"] != current:
             raise KnownPublishError("Workfile has changed during publishing!")
 
         if host.has_unsaved_changes():
-            self.log.info("Saving current file..")
+            self.log.info("Saving current file: {}".format(current))
             host.save_workfile()
         else:
             self.log.debug("Skipping workfile save because there are no "

openpype/modules/deadline/plugins/publish/submit_fusion_deadline.py

@@ -73,7 +73,7 @@ class FusionSubmitDeadline(
 
     def process(self, instance):
         if not instance.data.get("farm"):
-            self.log.info("Skipping local instance.")
+            self.log.debug("Skipping local instance.")
             return
 
         attribute_values = self.get_attr_values_from_data(

openpype/modules/deadline/plugins/publish/submit_nuke_deadline.py

@@ -86,7 +86,7 @@ class NukeSubmitDeadline(pyblish.api.InstancePlugin,
 
     def process(self, instance):
         if not instance.data.get("farm"):
-            self.log.info("Skipping local instance.")
+            self.log.debug("Skipping local instance.")
             return
 
         instance.data["attributeValues"] = self.get_attr_values_from_data(

openpype/modules/deadline/plugins/publish/submit_publish_job.py

@@ -762,7 +762,7 @@ class ProcessSubmittedJobOnFarm(pyblish.api.InstancePlugin):
 
         """
         if not instance.data.get("farm"):
-            self.log.info("Skipping local instance.")
+            self.log.debug("Skipping local instance.")
             return
 
         data = instance.data.copy()

openpype/modules/deadline/plugins/publish/validate_deadline_pools.py

@@ -26,7 +26,7 @@ class ValidateDeadlinePools(OptionalPyblishPluginMixin,
 
     def process(self, instance):
         if not instance.data.get("farm"):
-            self.log.info("Skipping local instance.")
+            self.log.debug("Skipping local instance.")
             return
 
         # get default deadline webservice url from deadline module

openpype/pipeline/publish/publish_plugins.py

@@ -379,7 +379,9 @@ class ColormanagedPyblishPluginMixin(object):
 
         # check if ext in lower case is in self.allowed_ext
         if ext.lstrip(".").lower() not in self.allowed_ext:
-            self.log.debug("Extension is not in allowed extensions.")
+            self.log.debug(
+                "Extension '{}' is not in allowed extensions.".format(ext)
+            )
             return
 
         if colorspace_settings is None:
@@ -393,8 +395,7 @@ class ColormanagedPyblishPluginMixin(object):
             self.log.warning("No colorspace management was defined")
             return
 
-        self.log.info("Config data is : `{}`".format(
-            config_data))
+        self.log.debug("Config data is: `{}`".format(config_data))
 
         project_name = context.data["projectName"]
         host_name = context.data["hostName"]
@@ -405,8 +406,7 @@ class ColormanagedPyblishPluginMixin(object):
         if isinstance(filename, list):
             filename = filename[0]
 
-        self.log.debug("__ filename: `{}`".format(
-            filename))
+        self.log.debug("__ filename: `{}`".format(filename))
 
         # get matching colorspace from rules
         colorspace = colorspace or get_imageio_colorspace_from_filepath(
@@ -415,8 +415,7 @@ class ColormanagedPyblishPluginMixin(object):
             file_rules=file_rules,
             project_settings=project_settings
         )
-        self.log.debug("__ colorspace: `{}`".format(
-            colorspace))
+        self.log.debug("__ colorspace: `{}`".format(colorspace))
 
         # infuse data to representation
         if colorspace:

openpype/plugins/publish/cleanup.py

@@ -81,7 +81,8 @@ class CleanUp(pyblish.api.InstancePlugin):
         staging_dir = instance.data.get("stagingDir", None)
 
         if not staging_dir:
-            self.log.info("Staging dir not set.")
+            self.log.debug("Skipping cleanup. Staging dir not set "
+                           "on instance: {}.".format(instance))
             return
 
         if not os.path.normpath(staging_dir).startswith(temp_root):
@@ -90,7 +91,7 @@ class CleanUp(pyblish.api.InstancePlugin):
             return
 
         if not os.path.exists(staging_dir):
-            self.log.info("No staging directory found: %s" % staging_dir)
+            self.log.debug("No staging directory found at: %s" % staging_dir)
             return
 
         if instance.data.get("stagingDir_persistent"):
@@ -131,7 +132,9 @@ class CleanUp(pyblish.api.InstancePlugin):
                     try:
                         os.remove(src)
                     except PermissionError:
-                        self.log.warning("Insufficient permission to delete {}".format(src))
+                        self.log.warning(
+                            "Insufficient permission to delete {}".format(src)
+                        )
                         continue
 
                     # add dir for cleanup

openpype/plugins/publish/collect_anatomy_context_data.py

@@ -67,5 +67,6 @@ class CollectAnatomyContextData(pyblish.api.ContextPlugin):
         # Store
         context.data["anatomyData"] = anatomy_data
 
-        self.log.info("Global anatomy Data collected")
-        self.log.debug(json.dumps(anatomy_data, indent=4))
+        self.log.debug("Global Anatomy Context Data collected:\n{}".format(
+            json.dumps(anatomy_data, indent=4)
+        ))

openpype/plugins/publish/collect_anatomy_instance_data.py

@@ -46,17 +46,17 @@ class CollectAnatomyInstanceData(pyblish.api.ContextPlugin):
     follow_workfile_version = False
 
     def process(self, context):
-        self.log.info("Collecting anatomy data for all instances.")
+        self.log.debug("Collecting anatomy data for all instances.")
 
         project_name = context.data["projectName"]
         self.fill_missing_asset_docs(context, project_name)
         self.fill_latest_versions(context, project_name)
         self.fill_anatomy_data(context)
 
-        self.log.info("Anatomy Data collection finished.")
+        self.log.debug("Anatomy Data collection finished.")
 
     def fill_missing_asset_docs(self, context, project_name):
-        self.log.debug("Qeurying asset documents for instances.")
+        self.log.debug("Querying asset documents for instances.")
 
         context_asset_doc = context.data.get("assetEntity")
 
@@ -271,7 +271,7 @@ class CollectAnatomyInstanceData(pyblish.api.ContextPlugin):
             instance_name = instance.data["name"]
             instance_label = instance.data.get("label")
             if instance_label:
-                instance_name += "({})".format(instance_label)
+                instance_name += " ({})".format(instance_label)
             self.log.debug("Anatomy data for instance {}: {}".format(
                 instance_name,
                 json.dumps(anatomy_data, indent=4)

openpype/plugins/publish/collect_anatomy_object.py

@@ -30,6 +30,6 @@ class CollectAnatomyObject(pyblish.api.ContextPlugin):
 
         context.data["anatomy"] = Anatomy(project_name)
 
-        self.log.info(
+        self.log.debug(
             "Anatomy object collected for project \"{}\".".format(project_name)
         )

openpype/plugins/publish/collect_custom_staging_dir.py

@@ -65,6 +65,6 @@ class CollectCustomStagingDir(pyblish.api.InstancePlugin):
         else:
             result_str = "Not adding"
 
-        self.log.info("{} custom staging dir for instance with '{}'".format(
+        self.log.debug("{} custom staging dir for instance with '{}'".format(
             result_str, family
         ))

openpype/plugins/publish/collect_from_create_context.py

@@ -92,5 +92,5 @@ class CollectFromCreateContext(pyblish.api.ContextPlugin):
 
         instance.data["transientData"] = transient_data
 
-        self.log.info("collected instance: {}".format(instance.data))
-        self.log.info("parsing data: {}".format(in_data))
+        self.log.debug("collected instance: {}".format(instance.data))
+        self.log.debug("parsing data: {}".format(in_data))

openpype/plugins/publish/collect_scene_version.py

@@ -48,10 +48,13 @@ class CollectSceneVersion(pyblish.api.ContextPlugin):
         if '<shell>' in filename:
             return
 
+        self.log.debug(
+            "Collecting scene version from filename: {}".format(filename)
+        )
+
         version = get_version_from_path(filename)
         assert version, "Cannot determine version"
 
         rootVersion = int(version)
         context.data['version'] = rootVersion
-        self.log.info("{}".format(type(rootVersion)))
         self.log.info('Scene Version: %s' % context.data.get('version'))

openpype/plugins/publish/extract_burnin.py

@@ -517,8 +517,8 @@ class ExtractBurnin(publish.Extractor):
         """
 
         if "burnin" not in (repre.get("tags") or []):
-            self.log.info((
-                "Representation \"{}\" don't have \"burnin\" tag. Skipped."
+            self.log.debug((
+                "Representation \"{}\" does not have \"burnin\" tag. Skipped."
             ).format(repre["name"]))
             return False
 

openpype/plugins/publish/extract_color_transcode.py

@@ -336,13 +336,13 @@ class ExtractOIIOTranscode(publish.Extractor):
 
         if repre.get("ext") not in self.supported_exts:
             self.log.debug((
-                    "Representation '{}' of unsupported extension. Skipped."
-            ).format(repre["name"]))
+                "Representation '{}' has unsupported extension: '{}'. Skipped."
+            ).format(repre["name"], repre.get("ext")))
             return False
 
         if not repre.get("files"):
             self.log.debug((
-                "Representation '{}' have empty files. Skipped."
+                "Representation '{}' has empty files. Skipped."
             ).format(repre["name"]))
             return False
 

openpype/plugins/publish/extract_review.py

@@ -92,8 +92,8 @@ class ExtractReview(pyblish.api.InstancePlugin):
         host_name = instance.context.data["hostName"]
         family = self.main_family_from_instance(instance)
 
-        self.log.info("Host: \"{}\"".format(host_name))
-        self.log.info("Family: \"{}\"".format(family))
+        self.log.debug("Host: \"{}\"".format(host_name))
+        self.log.debug("Family: \"{}\"".format(family))
 
         profile = filter_profiles(
             self.profiles,
@@ -351,7 +351,7 @@ class ExtractReview(pyblish.api.InstancePlugin):
             temp_data = self.prepare_temp_data(instance, repre, output_def)
             files_to_clean = []
             if temp_data["input_is_sequence"]:
-                self.log.info("Filling gaps in sequence.")
+                self.log.debug("Checking sequence to fill gaps in sequence..")
                 files_to_clean = self.fill_sequence_gaps(
                     files=temp_data["origin_repre"]["files"],
                     staging_dir=new_repre["stagingDir"],

openpype/plugins/publish/extract_thumbnail.py

@@ -36,7 +36,7 @@ class ExtractThumbnail(pyblish.api.InstancePlugin):
             ).format(subset_name))
             return
 
-        self.log.info(
+        self.log.debug(
             "Processing instance with subset name {}".format(subset_name)
         )
 
@@ -89,13 +89,13 @@ class ExtractThumbnail(pyblish.api.InstancePlugin):
 
             src_staging = os.path.normpath(repre["stagingDir"])
             full_input_path = os.path.join(src_staging, input_file)
-            self.log.info("input {}".format(full_input_path))
+            self.log.debug("input {}".format(full_input_path))
             filename = os.path.splitext(input_file)[0]
             jpeg_file = filename + "_thumb.jpg"
             full_output_path = os.path.join(dst_staging, jpeg_file)
 
             if oiio_supported:
-                self.log.info("Trying to convert with OIIO")
+                self.log.debug("Trying to convert with OIIO")
                 # If the input can read by OIIO then use OIIO method for
                 # conversion otherwise use ffmpeg
                 thumbnail_created = self.create_thumbnail_oiio(
@@ -148,7 +148,7 @@ class ExtractThumbnail(pyblish.api.InstancePlugin):
 
     def _already_has_thumbnail(self, repres):
         for repre in repres:
-            self.log.info("repre {}".format(repre))
+            self.log.debug("repre {}".format(repre))
             if repre["name"] == "thumbnail":
                 return True
         return False
@@ -173,20 +173,20 @@ class ExtractThumbnail(pyblish.api.InstancePlugin):
         return filtered_repres
 
     def create_thumbnail_oiio(self, src_path, dst_path):
-        self.log.info("outputting {}".format(dst_path))
+        self.log.info("Extracting thumbnail {}".format(dst_path))
         oiio_tool_path = get_oiio_tools_path()
         oiio_cmd = [
             oiio_tool_path,
             "-a", src_path,
             "-o", dst_path
         ]
-        self.log.info("running: {}".format(" ".join(oiio_cmd)))
+        self.log.debug("running: {}".format(" ".join(oiio_cmd)))
         try:
             run_subprocess(oiio_cmd, logger=self.log)
             return True
         except Exception:
             self.log.warning(
-                "Failed to create thubmnail using oiiotool",
+                "Failed to create thumbnail using oiiotool",
                 exc_info=True
             )
             return False

openpype/plugins/publish/extract_thumbnail_from_source.py

@@ -39,7 +39,7 @@ class ExtractThumbnailFromSource(pyblish.api.InstancePlugin):
         self._create_context_thumbnail(instance.context)
 
         subset_name = instance.data["subset"]
-        self.log.info(
+        self.log.debug(
             "Processing instance with subset name {}".format(subset_name)
         )
         thumbnail_source = instance.data.get("thumbnailSource")
@@ -104,7 +104,7 @@ class ExtractThumbnailFromSource(pyblish.api.InstancePlugin):
         full_output_path = os.path.join(dst_staging, dst_filename)
 
         if oiio_supported:
-            self.log.info("Trying to convert with OIIO")
+            self.log.debug("Trying to convert with OIIO")
             # If the input can read by OIIO then use OIIO method for
             # conversion otherwise use ffmpeg
             thumbnail_created = self.create_thumbnail_oiio(

openpype/plugins/publish/integrate.py

@@ -267,7 +267,7 @@ class IntegrateAsset(pyblish.api.InstancePlugin):
 
         instance_stagingdir = instance.data.get("stagingDir")
         if not instance_stagingdir:
-            self.log.info((
+            self.log.debug((
                 "{0} is missing reference to staging directory."
                 " Will try to get it from representation."
             ).format(instance))
@@ -480,7 +480,7 @@ class IntegrateAsset(pyblish.api.InstancePlugin):
                 update_data
             )
 
-        self.log.info("Prepared subset: {}".format(subset_name))
+        self.log.debug("Prepared subset: {}".format(subset_name))
         return subset_doc
 
     def prepare_version(self, instance, op_session, subset_doc, project_name):
@@ -521,7 +521,9 @@ class IntegrateAsset(pyblish.api.InstancePlugin):
                 project_name, version_doc["type"], version_doc
             )
 
-        self.log.info("Prepared version: v{0:03d}".format(version_doc["name"]))
+        self.log.debug(
+            "Prepared version: v{0:03d}".format(version_doc["name"])
+        )
 
         return version_doc
 

openpype/plugins/publish/integrate_legacy.py

@@ -147,7 +147,9 @@ class IntegrateAssetNew(pyblish.api.InstancePlugin):
 
     def process(self, instance):
         if instance.data.get("processedWithNewIntegrator"):
-            self.log.info("Instance was already processed with new integrator")
+            self.log.debug(
+                "Instance was already processed with new integrator"
+            )
             return
 
         for ef in self.exclude_families:
@@ -274,7 +276,7 @@ class IntegrateAssetNew(pyblish.api.InstancePlugin):
 
         stagingdir = instance.data.get("stagingDir")
         if not stagingdir:
-            self.log.info((
+            self.log.debug((
                 "{0} is missing reference to staging directory."
                 " Will try to get it from representation."
             ).format(instance))

openpype/plugins/publish/integrate_thumbnail.py

@@ -41,7 +41,7 @@ class IntegrateThumbnails(pyblish.api.ContextPlugin):
         # Filter instances which can be used for integration
         filtered_instance_items = self._prepare_instances(context)
         if not filtered_instance_items:
-            self.log.info(
+            self.log.debug(
                 "All instances were filtered. Thumbnail integration skipped."
             )
             return
@@ -162,7 +162,7 @@ class IntegrateThumbnails(pyblish.api.ContextPlugin):
 
             # Skip instance if thumbnail path is not available for it
             if not thumbnail_path:
-                self.log.info((
+                self.log.debug((
                     "Skipping thumbnail integration for instance \"{}\"."
                     " Instance and context"
                     " thumbnail paths are not available."