From ec77be20b730d3e6bec9d0f82fe24f480034a1c3 Mon Sep 17 00:00:00 2001 From: Paul Abumov Date: Tue, 8 Aug 2023 10:19:13 -0400 Subject: [PATCH 1/2] Added logging config for standalone scripts --- .../hydra/job_logging/mephisto_default.yaml | 5 +- mephisto/configs/__init__.py | 5 ++ mephisto/configs/logging.py | 53 ++++++++++++ mephisto/tools/examine_utils.py | 47 +++++++---- mephisto/utils/logger_core.py | 81 +++++-------------- 5 files changed, 117 insertions(+), 74 deletions(-) create mode 100644 mephisto/configs/__init__.py create mode 100644 mephisto/configs/logging.py diff --git a/hydra_configs/hydra/job_logging/mephisto_default.yaml b/hydra_configs/hydra/job_logging/mephisto_default.yaml index 0b6c66ddd..ffd538e7d 100644 --- a/hydra_configs/hydra/job_logging/mephisto_default.yaml +++ b/hydra_configs/hydra/job_logging/mephisto_default.yaml @@ -4,6 +4,9 @@ formatters: simple: format: "[%(asctime)s][%(name)s][%(levelname)s] - %(message)s" handlers: + console: + class: logging.StreamHandler + formatter: simple file: class: logging.FileHandler formatter: simple @@ -11,6 +14,6 @@ handlers: filename: ${hydra.runtime.output_dir}/${hydra.job.name}.log root: level: INFO - handlers: [file] + handlers: [console, file] disable_existing_loggers: false diff --git a/mephisto/configs/__init__.py b/mephisto/configs/__init__.py new file mode 100644 index 000000000..240697e32 --- /dev/null +++ b/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. diff --git a/mephisto/configs/logging.py b/mephisto/configs/logging.py new file mode 100644 index 000000000..8f900e7b9 --- /dev/null +++ b/mephisto/configs/logging.py @@ -0,0 +1,53 @@ +#!/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__))) +CONSOLE_LOG_LEVEL = os.environ.get("CONSOLE_LOG_LEVEL", "INFO") + +_now = datetime.now() +date_string = _now.strftime("%Y-%m-%d") +time_string = _now.strftime("%H-%M-%S") +executed_filename = os.path.splitext(os.path.basename(sys.argv[0]))[0] + +# Create dirs recursivelly if they do not exist +os.makedirs(os.path.join(BASE_DIR, "outputs", date_string, time_string), exist_ok=True) + +# Logging +LOGGING = { + "version": 1, + "disable_existing_loggers": True, + "formatters": { + "default": { + "format": "%(asctime)s - %(name)s - %(levelname)s - %(message)s", + }, + }, + "handlers": { + "console": { + "level": CONSOLE_LOG_LEVEL, + "class": "logging.StreamHandler", + "formatter": "default", + }, + "file": { + "level": "DEBUG", + "class": "logging.FileHandler", + "filename": os.path.join( + BASE_DIR, "outputs", date_string, time_string, f'{executed_filename}.log', + ), + "formatter": "default", + }, + }, + "loggers": { + "": { + "handlers": ["console", "file"], + "propagate": True, + "level": CONSOLE_LOG_LEVEL, + }, + }, +} diff --git a/mephisto/tools/examine_utils.py b/mephisto/tools/examine_utils.py index d0fbc82c5..a40676fca 100644 --- a/mephisto/tools/examine_utils.py +++ b/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') diff --git a/mephisto/utils/logger_core.py b/mephisto/utils/logger_core.py index 2e66a94c5..5db4795bd 100644 --- a/mephisto/utils/logger_core.py +++ b/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): From b4278a5425b062613baf1e58bc68da59f758e2f8 Mon Sep 17 00:00:00 2001 From: Paul Abumov Date: Tue, 8 Aug 2023 11:46:48 -0400 Subject: [PATCH 2/2] Fixed conflict with hydra logger --- mephisto/configs/logging.py | 56 ++++++++++++++++++++++++++----------- 1 file changed, 40 insertions(+), 16 deletions(-) diff --git a/mephisto/configs/logging.py b/mephisto/configs/logging.py index 8f900e7b9..30e5da4c1 100644 --- a/mephisto/configs/logging.py +++ b/mephisto/configs/logging.py @@ -9,17 +9,41 @@ from datetime import datetime BASE_DIR = os.path.dirname(os.path.dirname(os.path.dirname(__file__))) -CONSOLE_LOG_LEVEL = os.environ.get("CONSOLE_LOG_LEVEL", "INFO") +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") -executed_filename = os.path.splitext(os.path.basename(sys.argv[0]))[0] -# Create dirs recursivelly if they do not exist -os.makedirs(os.path.join(BASE_DIR, "outputs", date_string, time_string), exist_ok=True) -# Logging +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, @@ -30,24 +54,24 @@ }, "handlers": { "console": { - "level": CONSOLE_LOG_LEVEL, + "level": LOG_LEVEL, "class": "logging.StreamHandler", "formatter": "default", }, - "file": { - "level": "DEBUG", - "class": "logging.FileHandler", - "filename": os.path.join( - BASE_DIR, "outputs", date_string, time_string, f'{executed_filename}.log', - ), - "formatter": "default", - }, + **({ + "file": { + "level": LOG_LEVEL, + "class": "logging.FileHandler", + "filename": log_filename, + "formatter": "default", + } + } if "file" in log_handlers else {}), }, "loggers": { "": { - "handlers": ["console", "file"], + "handlers": log_handlers, "propagate": True, - "level": CONSOLE_LOG_LEVEL, + "level": LOG_LEVEL, }, }, }