Rework logging setup (#2575)

This allows projects to have more control over how Manticore logs are
handled. However, this also means that you need to explicitly enable
logging in Manticore scripts to see the logs. See
`manticore/__main__.py` file changes in this commit.

* Initialize Manticore logger for all tests

Co-authored-by: kokrui <[email protected]>

docs/utilities.rst

@@ -4,4 +4,7 @@ Utilities
 Logging
 ^^^^^^^
 
+.. autofunction:: manticore.utils.log.init_logging
+.. autofunction:: manticore.utils.log.get_manticore_logger_names
 .. autofunction:: manticore.utils.log.set_verbosity
+.. autofunction:: manticore.utils.log.default_handler

manticore/__main__.py

@@ -29,6 +29,7 @@ def main() -> None:
     """
     Dispatches execution into one of Manticore's engines: evm or native.
     """
+    log.init_logging()
     args = parse_arguments()
 
     if args.no_colors:
@@ -261,4 +262,6 @@ class ListEthereumDetectors(argparse.Action):
 
 
 if __name__ == "__main__":
+    # Only print with Manticore's logger
+    logging.getLogger().handlers = []
     main()

manticore/utils/log.py

@@ -2,36 +2,28 @@ import logging
 import sys
 import io
 
-from typing import List, Set, Tuple
+from typing import List, Tuple, Optional, Callable
 
 manticore_verbosity = 0
 DEFAULT_LOG_LEVEL = logging.WARNING
-all_loggers: Set[str] = set()
-default_factory = logging.getLogRecordFactory()
 logfmt = "%(asctime)s: [%(process)d] %(name)s:%(levelname)s %(message)s"
-handler = logging.StreamHandler(sys.stdout)
 formatter = logging.Formatter(logfmt)
-handler.setFormatter(formatter)
 
 
-class CallbackStream(io.TextIOBase):
+def get_manticore_logger_names() -> List[str]:
+    return [name for name in logging.root.manager.loggerDict if name.split(".", 1)[0] == "manticore"]  # type: ignore
+
+
+class CallbackStream(io.StringIO):
     def __init__(self, callback):
+        super().__init__()
         self.callback = callback
 
     def write(self, log_str):
         self.callback(log_str)
 
 
-def register_log_callback(cb):
-    for name in all_loggers:
-        logger = logging.getLogger(name)
-        handler_internal = logging.StreamHandler(CallbackStream(cb))
-        if name.startswith("manticore"):
-            handler_internal.setFormatter(formatter)
-        logger.addHandler(handler_internal)
-
-
-class ContextFilter(logging.Filter):
+class ManticoreContextFilter(logging.Filter):
     """
     This is a filter which injects contextual information into the log.
     """
@@ -71,39 +63,21 @@ class ContextFilter(logging.Filter):
         else:
             return self.colored_levelname_format.format(self.color_map[levelname], levelname)
 
-    def filter(self, record) -> bool:
+    def filter(self, record: logging.LogRecord) -> bool:
+        if not record.name.startswith("manticore"):
+            return True
+
         record.name = self.summarized_name(record.name)
         record.levelname = self.colored_level_name(record.levelname)
         return True
 
 
-ctxfilter = ContextFilter()
-
-
-class CustomLogger(logging.Logger):
-    """
-    Custom Logger class that can grab the correct verbosity level from this module
-    """
-
-    def __init__(self, name: str, level=DEFAULT_LOG_LEVEL, *args) -> None:
-        super().__init__(name, min(get_verbosity(name), level), *args)
-        all_loggers.add(name)
-        self.initialized = False
-
-        if name.startswith("manticore"):
-            self.addHandler(handler)
-            self.addFilter(ctxfilter)
-            self.propagate = False
-
-
-logging.setLoggerClass(CustomLogger)
-
-
 def disable_colors() -> None:
-    ContextFilter.colors_disabled = True
+    ManticoreContextFilter.colors_disabled = True
 
 
 def get_levels() -> List[List[Tuple[str, int]]]:
+    all_loggers = get_manticore_logger_names()
     return [
         # 0
         [(x, DEFAULT_LOG_LEVEL) for x in all_loggers],
@@ -171,9 +145,43 @@ def set_verbosity(setting: int) -> None:
     """Set the global verbosity (0-5)."""
     global manticore_verbosity
     manticore_verbosity = min(max(setting, 0), len(get_levels()) - 1)
-    for logger_name in all_loggers:
+    for logger_name in get_manticore_logger_names():
         logger = logging.getLogger(logger_name)
         # min because more verbosity == lower numbers
         # This means if you explicitly call setLevel somewhere else in the source, and it's *more*
         # verbose, it'll stay that way even if manticore_verbosity is 0.
         logger.setLevel(min(get_verbosity(logger_name), logger.getEffectiveLevel()))
+
+
+def register_log_callback(callback: Callable[[Optional[str]], None]) -> None:
+    callback_handler = logging.StreamHandler(CallbackStream(callback))
+    callback_handler.setFormatter(formatter)
+    callback_handler.addFilter(ManticoreContextFilter())
+    init_logging(callback_handler)
+
+
+def default_handler() -> logging.Handler:
+    """Return a default Manticore logger with a nice formatter and filter."""
+    handler = logging.StreamHandler(sys.stdout)
+    handler.setFormatter(formatter)
+    handler.addFilter(ManticoreContextFilter())
+    return handler
+
+
+def init_logging(handler: Optional[logging.Handler] = None) -> None:
+    """
+    Initialize logging for Manticore, given a handler or by default use `default_logger()`
+    """
+    logger = logging.getLogger("manticore")
+    logger.parent = None  # type: ignore
+
+    # Explicitly set the level so that we don't use root's. If root is at DEBUG,
+    # then _a lot_ of logs will be printed if the user forgets to set
+    # manticore's logger
+    logger.setLevel(DEFAULT_LOG_LEVEL)
+
+    if handler is None:
+        handler = default_handler()
+
+    # Finally attach to Manticore
+    logger.addHandler(handler)

tests/conftest.py

@@ -0,0 +1,9 @@
+import pytest
+
+from manticore.utils import log
+
+
+@pytest.fixture(scope="session", autouse=True)
+def initialize_manticore_logging(request):
+    """Initialize Manticore's logger for all tests"""
+    log.init_logging()