Merge pull request #2845 from alicevision/dev/update_chunk_logger

[core] Setup logger to be able to use logging in plugins

Author: cbentejac

bin/meshroom_batch

@@ -8,7 +8,7 @@ import re
 import sys
 
 import meshroom.core.graph
-from meshroom import setupEnvironment
+from meshroom import setupEnvironment, logStringToPython
 
 setupEnvironment()
 
@@ -135,14 +135,6 @@ advanced_group.add_argument(
 
 args = parser.parse_args()
 
-logStringToPython = {
-    'fatal': logging.FATAL,
-    'error': logging.ERROR,
-    'warning': logging.WARNING,
-    'info': logging.INFO,
-    'debug': logging.DEBUG,
-    'trace': logging.DEBUG,
-}
 logging.getLogger().setLevel(logStringToPython[args.verbose])
 
 if not args.input and not args.inputRecursive:

bin/meshroom_compute

@@ -95,13 +95,15 @@ if args.node:
         # Restore the log level
         logging.getLogger().setLevel(meshroom.logStringToPython[args.verbose])
 
+    node.prepareLogger(args.iteration)
     node.preprocess()
     if args.iteration != -1:
         chunk = node.chunks[args.iteration]
         chunk.process(args.forceCompute, args.inCurrentEnv)
     else:
         node.process(args.forceCompute, args.inCurrentEnv)
     node.postprocess()
+    node.restoreLogger()
 else:
     if args.iteration != -1:
         print('Error: "--iteration" only make sense when used with "--node".')

meshroom/__init__.py

@@ -48,13 +48,32 @@ class VersionStatus(Enum):
 
 useMultiChunks = util.strtobool(os.environ.get("MESHROOM_USE_MULTI_CHUNKS", "True"))
 
+# Logging
+
+def addTraceLevel():
+    """ From https://stackoverflow.com/a/35804945 """
+    levelName, methodName, levelNum = 'TRACE', 'trace', logging.DEBUG - 5
+    if hasattr(logging, levelName) or hasattr(logging, methodName)or hasattr(logging.getLoggerClass(), methodName):
+       return
+    def logForLevel(self, message, *args, **kwargs):
+        if self.isEnabledFor(levelNum):
+            self._log(levelNum, message, args, **kwargs)
+    def logToRoot(message, *args, **kwargs):
+        logging.log(levelNum, message, *args, **kwargs)
+
+    logging.addLevelName(levelNum, levelName)
+    setattr(logging, levelName, levelNum)
+    setattr(logging.getLoggerClass(), methodName, logForLevel)
+    setattr(logging, methodName, logToRoot)
+
+addTraceLevel()
 logStringToPython = {
-    'fatal': logging.FATAL,
+    'fatal': logging.CRITICAL,
     'error': logging.ERROR,
     'warning': logging.WARNING,
     'info': logging.INFO,
     'debug': logging.DEBUG,
-    'trace': logging.DEBUG,
+    'trace': logging.TRACE,
 }
 logging.getLogger().setLevel(logStringToPython[os.environ.get('MESHROOM_VERBOSE', 'warning')])
 

meshroom/core/desc/node.py

@@ -9,10 +9,11 @@
 import sys
 
 from .computation import Level, StaticNodeSize
-from .attribute import StringParam, ColorParam
+from .attribute import StringParam, ColorParam, ChoiceParam
 
 import meshroom
 from meshroom.core import cgroup
+from meshroom.core.utils import VERBOSE_LEVEL
 
 _MESHROOM_ROOT = Path(meshroom.__file__).parent.parent.as_posix()
 _MESHROOM_COMPUTE = (Path(_MESHROOM_ROOT) / "bin" / "meshroom_compute").as_posix()
@@ -67,6 +68,14 @@ class BaseNode(object):
             value="",
             invalidate=False,
         ),
+        ChoiceParam(
+            name="nodeDefaultLogLevel",
+            label="Default Logging Level",
+            description="Default logging level for the node (critical, error, warning, info, debug).",
+            value="info",
+            values=VERBOSE_LEVEL,
+            invalidate=False,
+        ),
         ColorParam(
             name="color",
             label="Color",

meshroom/core/node.py

@@ -14,14 +14,14 @@
 import uuid
 from collections import namedtuple, OrderedDict
 from enum import Enum, auto
-from typing import Callable, Optional
-
+from typing import Callable, Optional, List
 
 import meshroom
 from meshroom.common import Signal, Variant, Property, BaseObject, Slot, ListModel, DictModel
 from meshroom.core import desc, plugins, stats, hashValue, nodeVersion, Version, MrNodeType
 from meshroom.core.attribute import attributeFactory, ListAttribute, GroupAttribute, Attribute
 from meshroom.core.exception import NodeUpgradeError, UnknownNodeTypeError
+from meshroom.core.mtyping import PathLike
 
 
 def getWritingFilepath(filepath: str) -> str:
@@ -221,9 +221,11 @@ def fromDict(self, d):
 class LogManager:
     dateTimeFormatting = '%H:%M:%S'
 
-    def __init__(self, chunk):
-        self.chunk = chunk
-        self.logger = logging.getLogger(chunk.node.getName())
+    def __init__(self, logger, logFile):
+        self.logger: logging.Logger = logger
+        self.logFile: PathLike = logFile
+        self._previousHandlers: List[logging.Handler] = []
+        self._previousLevel: int = 0
 
     class Formatter(logging.Formatter):
         def format(self, record):
@@ -232,19 +234,29 @@ def format(self, record):
             return logging.Formatter.format(self, record)
 
     def configureLogger(self):
+        self._previousLevel = self.logger.level
+        self._previousHandlers = []
         for handler in self.logger.handlers[:]:
+            self._previousHandlers.append(handler)
             self.logger.removeHandler(handler)
-        handler = logging.FileHandler(self.chunk.logFile)
+        handler = logging.FileHandler(self.logFile)
         formatter = self.Formatter('[%(asctime)s.%(msecs)03d][%(levelname)s] %(message)s',
                                    self.dateTimeFormatting)
         handler.setFormatter(formatter)
         self.logger.addHandler(handler)
 
+    def restorePreviousLogger(self):
+        for h in self.logger.handlers[:]:
+            self.logger.removeHandler(h)
+        for h in self._previousHandlers:
+            self.logger.addHandler(h)
+        self.logger.setLevel(self._previousLevel)
+
     def start(self, level):
         # Clear log file
-        open(self.chunk.logFile, 'w').close()
-
+        open(self.logFile, 'w').close()
         self.configureLogger()
+        self.logger.propagate = False
         self.logger.setLevel(self.textToLevel(level))
         self.progressBar = False
 
@@ -261,15 +273,15 @@ def makeProgressBar(self, end, message=''):
         self.currentProgressTics = 0
         self.progressBar = True
 
-        with open(self.chunk.logFile, 'a') as f:
+        with open(self.logFile, 'a') as f:
             if message:
                 f.write(message+'\n')
             f.write('0%   10   20   30   40   50   60   70   80   90   100%\n')
             f.write('|----|----|----|----|----|----|----|----|----|----|\n\n')
 
             f.close()
 
-        with open(self.chunk.logFile) as f:
+        with open(self.logFile) as f:
             content = f.read()
             self.progressBarPosition = content.rfind('\n')
 
@@ -281,7 +293,7 @@ def updateProgressBar(self, value):
 
         tics = round((value/self.progressEnd)*51)
 
-        with open(self.chunk.logFile, 'r+') as f:
+        with open(self.logFile, 'r+') as f:
             text = f.read()
             for i in range(tics-self.currentProgressTics):
                 text = text[:self.progressBarPosition]+'*'+text[self.progressBarPosition:]
@@ -296,8 +308,10 @@ def completeProgressBar(self):
 
         self.progressBar = False
 
-    def textToLevel(self, text):
-        if text == "critical":
+    @staticmethod
+    def textToLevel(text):
+        text = text.lower()
+        if text in ["critical", "fatal"]:
             return logging.CRITICAL
         elif text == "error":
             return logging.ERROR
@@ -307,6 +321,8 @@ def textToLevel(self, text):
             return logging.INFO
         elif text == "debug":
             return logging.DEBUG
+        elif text == "trace":
+            return logging.TRACE
         else:
             return logging.NOTSET
 
@@ -325,7 +341,7 @@ def __init__(self, node, range, parent=None):
         super().__init__(parent)
         self.node = node
         self.range = range
-        self.logManager: LogManager = LogManager(self)
+        self._logManager = None
         self._status: StatusData = StatusData(node.name, node.nodeType, node.packageName,
                                               node.packageVersion, node.getMrNodeType())
         self.statistics: stats.Statistics = stats.Statistics()
@@ -344,6 +360,13 @@ def name(self):
             return f"{self.node.name}({self.index})"
         else:
             return self.node.name
+    
+    @property
+    def logManager(self):
+        if self._logManager is None:
+            logger = logging.getLogger(self.node.getName())
+            self._logManager = LogManager(logger, self.logFile)
+        return self._logManager
 
     @property
     def statusName(self):
@@ -660,6 +683,7 @@ def __init__(self, nodeType: str, position: Position = None, parent: BaseObject
         self._uid: str = uid
         self._cmdVars: dict = {}
         self._size: int = 0
+        self._logManager: Optional[LogManager] = None
         self._position: Position = position or Position()
         self._attributes = DictModel(keyAttrName='name', parent=self)
         self._internalAttributes = DictModel(keyAttrName='name', parent=self)
@@ -705,6 +729,15 @@ def getLabel(self):
                 return label
         return self.getDefaultLabel()
 
+    def getNodeLogLevel(self):
+        """
+        Returns:
+            str: the user-provided log level used for logging on process launched by this node
+        """
+        if self.hasInternalAttribute("nodeDefaultLogLevel"):
+            return self.internalAttribute("nodeDefaultLogLevel").value.strip()
+        return "info"
+    
     def getColor(self):
         """
         Returns:
@@ -1312,6 +1345,24 @@ def postprocess(self):
         # node is completed
         self.nodeDesc.postprocess(self)
 
+    def getLogHandlers(self):
+        return self._handlers
+
+    def prepareLogger(self, iteration=-1):
+        # Get file handler path
+        logFileName = "log"
+        if iteration != -1:
+            chunk = self.chunks[iteration]
+            logFileName = str(chunk.index) + ".log"
+        logFile = os.path.join(self.graph.cacheDir, self.internalFolder, logFileName)
+        # Setup logger
+        rootLogger = logging.getLogger()
+        self._logManager = LogManager(rootLogger, logFile)
+        self._logManager.start(self.getNodeLogLevel())
+
+    def restoreLogger(self):
+        self._logManager.restorePreviousLogger()
+
     def updateOutputAttr(self):
         if not self.nodeDesc:
             return

meshroom/core/nodeFactory.py

@@ -174,13 +174,15 @@ def _checkAttributesCompatibility(
 
     def _createNode(self) -> Node:
         logging.info(f"Creating node '{self.name}'")
-        # TODO: user inputs/outputs may conflicts with internal names (like position, uid)
+        # TODO: user inputs/outputs may conflicts with internal names (like logLevel, position, uid)
+        # The line below can cause UI issues but at least prevent crashes
+        internalInputs = {k: v for k, v in self.internalInputs.items() if k not in self.inputs.keys()}
         return Node(
             self.nodeType,
             position=self.position,
             uid=self.uid,
             **self.inputs,
-            **self.internalInputs,
+            **internalInputs,
             **self.outputs,
         )