Improve logger in Python code

hydra_configs/hydra/job_logging/mephisto_default.yaml

@@ -4,13 +4,16 @@ formatters:
   simple:
     format: "[%(asctime)s][%(name)s][%(levelname)s] - %(message)s"
 handlers:
+  console:
+    class: logging.StreamHandler
+    formatter: simple
   file:
     class: logging.FileHandler
     formatter: simple
     # absolute file path
     filename: ${hydra.runtime.output_dir}/${hydra.job.name}.log
 root:
   level: INFO
-  handlers: [file]
+  handlers: [console, file]
 
 disable_existing_loggers: false

mephisto/configs/__init__.py

@@ -0,0 +1,5 @@
+#!/usr/bin/env python3
+
+# Copyright (c) Facebook, Inc. and its affiliates.
+# This source code is licensed under the MIT license found in the
+# LICENSE file in the root directory of this source tree.

mephisto/configs/logging.py

@@ -0,0 +1,77 @@
+#!/usr/bin/env python3
+
+# Copyright (c) Facebook, Inc. and its affiliates.
+# This source code is licensed under the MIT license found in the
+# LICENSE file in the root directory of this source tree.
+
+import os
+import sys
+from datetime import datetime
+
+BASE_DIR = os.path.dirname(os.path.dirname(os.path.dirname(__file__)))
+LOG_LEVEL = os.environ.get("LOG_LEVEL", "INFO")
+WRITE_LOG_TO_FILE = os.environ.get("WRITE_LOG_TO_FILE", '0')
+
+_now = datetime.now()
+date_string = _now.strftime("%Y-%m-%d")
+time_string = _now.strftime("%H-%M-%S")
+
+
+def get_log_handlers():
+    """ We enable module-level loggers via env variable (that we can set in the console),
+        so that hydra doesn't create an empty file for every module-level logger
+    """
+    handlers = ["console"]
+    if WRITE_LOG_TO_FILE == '1':
+        handlers.append("file")
+        # Create dirs recursivelly if they do not exist
+        os.makedirs(
+            os.path.join(BASE_DIR, "outputs", date_string, time_string),
+            exist_ok=True
+        )
+    return handlers
+
+
+def get_log_filename():
+    """ Compose logfile path formatted same way as hydra """
+    executed_filename = os.path.splitext(os.path.basename(sys.argv[0]))[0]
+    return os.path.join(
+        BASE_DIR, "outputs", date_string, time_string, f'{executed_filename}.log',
+    )
+
+
+log_handlers = get_log_handlers()
+log_filename = get_log_filename()
+
+# Logging config
+LOGGING = {
+    "version": 1,
+    "disable_existing_loggers": True,
+    "formatters": {
+        "default": {
+            "format": "%(asctime)s - %(name)s - %(levelname)s - %(message)s",
+        },
+    },
+    "handlers": {
+        "console": {
+            "level": LOG_LEVEL,
+            "class": "logging.StreamHandler",
+            "formatter": "default",
+        },
+        **({
+            "file": {
+                "level": LOG_LEVEL,
+                "class": "logging.FileHandler",
+                "filename": log_filename,
+                "formatter": "default",
+            }
+        } if "file" in log_handlers else {}),
+    },
+    "loggers": {
+        "": {
+            "handlers": log_handlers,
+            "propagate": True,
+            "level": LOG_LEVEL,
+        },
+    },
+}

mephisto/tools/examine_utils.py

@@ -7,14 +7,19 @@
 Utilities specifically for running examine scripts. Example usage can be
 seen in the examine results scripts in the examples directory.
 """
-import traceback
 
-from mephisto.tools.data_browser import DataBrowser
+from typing import Any
+from typing import Callable
+from typing import Dict
+from typing import List
+from typing import Optional
+from typing import Tuple
+from typing import TYPE_CHECKING
+
 from mephisto.data_model.worker import Worker
-from mephisto.utils.qualifications import find_or_create_qualification
+from mephisto.tools.data_browser import DataBrowser
 from mephisto.utils.logger_core import get_logger
-
-from typing import TYPE_CHECKING, Optional, Tuple, Callable, Dict, Any, List
+from mephisto.utils.qualifications import find_or_create_qualification
 
 if TYPE_CHECKING:
     from mephisto.abstractions.database import MephistoDB
@@ -63,7 +68,7 @@ def print_results(
     units.reverse()
 
     for unit in units[start:end]:
-        print(_get_and_format_data(data_browser, format_data_for_printing, unit))
+        logger.info(_get_and_format_data(data_browser, format_data_for_printing, unit))
 
 
 def prompt_for_options(
@@ -133,7 +138,11 @@ def format_worker_stats(
     accepted_work = len(prev_work["accepted"])
     soft_rejected_work = len(prev_work["soft_rejected"])
     rejected_work = len(prev_work["rejected"])
-    return f"({accepted_work} | {rejected_work + soft_rejected_work}({soft_rejected_work}) / {accepted_work + soft_rejected_work + rejected_work})"
+    return (
+        f"({accepted_work} | "
+        f"{rejected_work + soft_rejected_work}({soft_rejected_work}) / "
+        f"{accepted_work + soft_rejected_work + rejected_work})"
+    )
 
 
 def run_examine_by_worker(
@@ -167,16 +176,17 @@ def run_examine_by_worker(
     if block_qualification is not None:
         created_block_qual = find_or_create_qualification(db, block_qualification)
         print(
-            "When you pass or reject a task, the script gives you an option to disqualify the worker "
-            "from future tasks by assigning a qualification. If provided, this worker will no "
-            "longer be able to work on tasks where the set --block-qualification shares the same name "
-            f"you provided above: {block_qualification}\n"
+            "When you pass or reject a task, the script gives you an option to disqualify the "
+            "worker from future tasks by assigning a qualification. "
+            "If provided, this worker will no longer be able to work on tasks where the set "
+            "--block-qualification shares the same name you provided above: {block_qualification}\n"
         )
     if approve_qualification is not None:
         created_approve_qual = find_or_create_qualification(db, approve_qualification)
         print(
             "You may use this script to establish a qualified worker pool by granting the provided "
-            f"approve qualification {approve_qualification} to workers you think understand the task "
+            f"approve qualification {approve_qualification} "
+            f"to workers you think understand the task "
             "well. This will be provided as an option for workers you (A)pprove all on. "
             "Future tasks can use this qual as a required qualification, as described in the "
             "common qualification flows document."
@@ -226,11 +236,13 @@ def run_examine_by_worker(
                 decision = apply_all_decision
             else:
                 decision = input(
-                    "Do you want to accept this work? (a)ccept, (r)eject, (p)ass: "
+                    "Do you want to accept this work? "
+                    "(a)ccept, (r)eject, (p)ass: "
                 )
             while decision.lower() not in options:
                 decision = input(
-                    "Decision must be one of a, p, r. Use CAPS to apply to all remaining for worker: "
+                    "Decision must be one of a, p, r. "
+                    "Use CAPS to apply to all remaining for worker: "
                 )
 
             agent = unit.get_assigned_agent()
@@ -288,6 +300,8 @@ def run_examine_or_review(
     )
 
     if do_review.lower().startswith("r"):
+        logger.info('Start reviewing results')
+
         run_examine_by_worker(db, format_data_for_printing)
     else:
         start = 0
@@ -299,4 +313,9 @@ def run_examine_or_review(
             start = int(opts[1])
             end = int(opts[2])
         task_name = input("Input task name: ")
+
+        logger.info(f'Start examining results for task "{task_name}"')
+
         print_results(db, task_name, format_data_for_printing, start=start, end=end)
+
+    logger.info('End examining results')

mephisto/utils/logger_core.py

@@ -5,11 +5,16 @@
 # LICENSE file in the root directory of this source tree.
 
 import logging
-from logging.handlers import RotatingFileHandler
-from typing import Any, List, Optional, Dict, Set
-from rich.logging import RichHandler
-from mephisto.utils.rich import console
+import os
+from logging.config import dictConfig
+from typing import Optional, Dict, Set
+from werkzeug.utils import import_string
 
+BOLD_RED = "\u001b[31;1m"
+RESET = "\u001b[0m"
+LOGGING_MODULE = os.environ.get("LOGGING_MODULE", "mephisto.configs.logging")
+
+logging_module = import_string(LOGGING_MODULE)
 loggers: Dict[str, logging.Logger] = {}
 global_log_level = logging.INFO
 _seen_logs: Set[str] = set()
@@ -24,7 +29,7 @@ def warn_once(msg: str) -> None:
     global _seen_logs
     if msg not in _seen_logs:
         _seen_logs.add(msg)
-        logging.warn(msg)
+        logging.warning(msg)
 
 
 def set_mephisto_log_level(verbose: Optional[bool] = None, level: Optional[str] = None):
@@ -54,66 +59,24 @@ def set_mephisto_log_level(verbose: Optional[bool] = None, level: Optional[str]
         logger.setLevel(global_log_level)
 
 
-def get_logger(
-    name: str,
-    verbose: Optional[bool] = None,
-    log_file: Optional[str] = None,
-    level: Optional[str] = None,
-) -> logging.Logger:
+def get_logger(name: str) -> logging.Logger:
     """
     Gets the logger corresponds to each module
-            Parameters:
-                    name (string): the module name (__name__).
-                    verbose (bool): INFO level activated if True.
-                    log_file (string): path for saving logs locally.
-                    level (string): logging level. Values options: [info, debug, warning, error, critical].
-
-            Returns:
-                    logger (logging.Logger): the corresponding logger to the given module name.
+        Parameters:
+            name (string): the module name (__name__).
+
+        Returns:
+            logger (logging.Logger): the corresponding logger to the given module name.
     """
-    LOGFORMAT = "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
-    LOGFORMAT_RICH = "%(message)s"
+    dictConfig(logging_module.LOGGING)
+
     global loggers
-    found_logger = loggers.get(name)
-    if found_logger is not None:
+    if found_logger := loggers.get(name):
         return found_logger
-    else:
-
-        level_dict = {
-            "debug": logging.DEBUG,
-            "info": logging.INFO,
-            "warning": logging.WARNING,
-            "error": logging.ERROR,
-            "critical": logging.CRITICAL,
-        }
-        ch = RichHandler()
-        ch.setFormatter(logging.Formatter(LOGFORMAT_RICH))
-        logging_format: List[Any] = [ch]
-        if log_file is not None:
-            logging_format.append(RotatingFileHandler(log_file))
-        logging.basicConfig(
-            level=level_dict[level.lower()] if level is not None else logging.INFO,
-            format=LOGFORMAT,
-            handlers=logging_format,
-        )
-
-        logger = logging.getLogger(name)
-
-        logger.addHandler(ch)
-
-        if level is not None:
-            logger.setLevel(level_dict[level.lower()])
-        elif verbose is not None:
-            logger.setLevel(logging.DEBUG if verbose else logging.INFO)
-        else:
-            logger.setLevel(global_log_level)
-
-        loggers[name] = logger
-        return logger
-
 
-BOLD_RED = "\u001b[31;1m"
-RESET = "\u001b[0m"
+    logger = logging.getLogger(name)
+    loggers[name] = logger
+    return logger
 
 
 def format_loud(target_text: str):