diff --git a/docs/resources/log.config b/docs/resources/log.config index 07c2963686..a245312cf7 100644 --- a/docs/resources/log.config +++ b/docs/resources/log.config @@ -1,28 +1,77 @@ -[loggers] -keys=root - -[handlers] -keys=consoleHandler,errorFileHandler - -[formatters] -keys=baseFormatter - -[logger_root] -level=INFO -handlers=consoleHandler,errorFileHandler - -[handler_consoleHandler] -class=StreamHandler -level=DEBUG -formatter=baseFormatter -args=(sys.stdout,) - -[handler_errorFileHandler] -class=FileHandler -level=ERROR -formatter=baseFormatter -args=('error_log.txt', 'a') - -[formatter_baseFormatter] -class=nvflare.fuel.utils.log_utils.BaseFormatter -format=%(asctime)s - %(name)s - %(levelname)s - %(message)s \ No newline at end of file +{ + "version": 1, + "disable_existing_loggers": false, + "formatters": { + "baseFormatter": { + "()": "nvflare.fuel.utils.log_utils.BaseFormatter", + "fmt": "%(asctime)s - %(name)s - %(levelname)s - %(message)s" + }, + "colorFormatter": { + "()": "nvflare.fuel.utils.log_utils.ColorFormatter", + "fmt": "%(asctime)s - %(name)s - %(levelname)s - %(message)s" + }, + "jsonFormatter": { + "()": "nvflare.fuel.utils.log_utils.JsonFormatter", + "fmt": "%(asctime)s - %(name)s - %(fullName)s - %(levelname)s - %(message)s" + } + }, + "filters": { + "FLFilter": { + "()": "nvflare.fuel.utils.log_utils.LoggerNameFilter", + "logger_names": ["custom", "nvflare.app_common", "nvflare.app_opt"] + } + }, + "handlers": { + "consoleHandler": { + "class": "logging.StreamHandler", + "level": "DEBUG", + "formatter": "colorFormatter", + "filters": [], + "stream": "ext://sys.stdout" + }, + "logFileHandler": { + "class": "logging.handlers.RotatingFileHandler", + "level": "DEBUG", + "formatter": "baseFormatter", + "filename": "log.txt", + "mode": "a", + "maxBytes": 20971520, + "backupCount": 10 + }, + "errorFileHandler": { + "class": "logging.handlers.RotatingFileHandler", + "level": "ERROR", + "formatter": "baseFormatter", + "filename": "log_error.txt", + "mode": "a", + "maxBytes": 20971520, + "backupCount": 10 + }, + "jsonFileHandler": { + "class": "logging.handlers.RotatingFileHandler", + "level": "DEBUG", + "formatter": "jsonFormatter", + "filename": "log.json", + "mode": "a", + "maxBytes": 20971520, + "backupCount": 10 + }, + "FLFileHandler": { + "class": "logging.handlers.RotatingFileHandler", + "level": "DEBUG", + "formatter": "baseFormatter", + "filters": ["FLFilter"], + "filename": "log_fl.txt", + "mode": "a", + "maxBytes": 20971520, + "backupCount": 10, + "delay": true + } + }, + "loggers": { + "root": { + "level": "INFO", + "handlers": ["consoleHandler", "logFileHandler", "errorFileHandler", "jsonFileHandler", "FLFileHandler"] + } + } +} \ No newline at end of file diff --git a/nvflare/apis/fl_constant.py b/nvflare/apis/fl_constant.py index a84a89669c..d03e456ad3 100644 --- a/nvflare/apis/fl_constant.py +++ b/nvflare/apis/fl_constant.py @@ -382,7 +382,7 @@ class WorkspaceConstants: SITE_FOLDER_NAME = "local" CUSTOM_FOLDER_NAME = "custom" - LOGGING_CONFIG = "log.config" + LOGGING_CONFIG = "log_config.json" DEFAULT_LOGGING_CONFIG = LOGGING_CONFIG + ".default" AUDIT_LOG = "audit.log" LOG_FILE_NAME = "log.txt" diff --git a/nvflare/app_common/tie/py_applet.py b/nvflare/app_common/tie/py_applet.py index 148b415871..406bb61307 100644 --- a/nvflare/app_common/tie/py_applet.py +++ b/nvflare/app_common/tie/py_applet.py @@ -12,14 +12,13 @@ # See the License for the specific language governing permissions and # limitations under the License. import multiprocessing -import os import sys import threading import time from abc import ABC, abstractmethod from nvflare.apis.workspace import Workspace -from nvflare.fuel.utils.log_utils import add_log_file_handler, configure_logging +from nvflare.fuel.utils.log_utils import configure_logging from nvflare.security.logging import secure_format_exception, secure_log_traceback from .applet import Applet @@ -94,9 +93,7 @@ def start(self, app_ctx: dict): if not self.in_process: # enable logging run_dir = self.workspace.get_run_dir(self.job_id) - log_file_name = os.path.join(run_dir, "applet_log.txt") - configure_logging(self.workspace) - add_log_file_handler(log_file_name) + configure_logging(self.workspace, dir_path=run_dir, file_prefix="applet") self.runner.start(app_ctx) # Note: run_func does not return until it runs to completion! diff --git a/nvflare/app_opt/xgboost/histogram_based_v2/adaptors/adaptor.py b/nvflare/app_opt/xgboost/histogram_based_v2/adaptors/adaptor.py index f252ffdb92..64c9be5f22 100644 --- a/nvflare/app_opt/xgboost/histogram_based_v2/adaptors/adaptor.py +++ b/nvflare/app_opt/xgboost/histogram_based_v2/adaptors/adaptor.py @@ -27,7 +27,7 @@ from nvflare.apis.workspace import Workspace from nvflare.app_opt.xgboost.histogram_based_v2.defs import Constant from nvflare.app_opt.xgboost.histogram_based_v2.runners.xgb_runner import AppRunner -from nvflare.fuel.utils.log_utils import add_log_file_handler, configure_logging, get_obj_logger +from nvflare.fuel.utils.log_utils import configure_logging, get_obj_logger from nvflare.fuel.utils.validation_utils import check_object_type from nvflare.security.logging import secure_format_exception, secure_log_traceback @@ -65,8 +65,7 @@ def start(self, ctx: dict): run_dir = self.workspace.get_run_dir(self.job_id) log_file_name = os.path.join(run_dir, f"{self.app_name}_log.txt") print(f"XGB Log: {log_file_name}") - configure_logging(self.workspace) - add_log_file_handler(log_file_name) + configure_logging(self.workspace, dir_path=run_dir, file_prefix=self.app_name) self.runner.run(ctx) self.stopped = True except Exception as e: diff --git a/nvflare/fuel/utils/log_utils.py b/nvflare/fuel/utils/log_utils.py index 77a855e126..e889d22759 100644 --- a/nvflare/fuel/utils/log_utils.py +++ b/nvflare/fuel/utils/log_utils.py @@ -12,9 +12,11 @@ # See the License for the specific language governing permissions and # limitations under the License. import inspect +import json import logging import logging.config import os +import re from logging import Logger from logging.handlers import RotatingFileHandler @@ -22,35 +24,61 @@ class ANSIColor: - GREY = "38" - YELLOW = "33" - RED = "31" - BOLD_RED = "31;1" - CYAN = "36" - RESET = "0" + # Basic ANSI color codes + COLORS = { + "black": "30", + "red": "31", + "bold_red": "31;1", + "green": "32", + "yellow": "33", + "blue": "34", + "magenta": "35", + "cyan": "36", + "white": "37", + "grey": "38", + "reset": "0", + } + + # Default logger level:color mappings + DEFAULT_LEVEL_COLORS = { + "NOTSET": COLORS["grey"], + "DEBUG": COLORS["grey"], + "INFO": COLORS["grey"], + "WARNING": COLORS["yellow"], + "ERROR": COLORS["red"], + "CRITICAL": COLORS["bold_red"], + } + + @classmethod + def colorize(cls, text: str, color: str) -> str: + """Wrap text with the given ANSI SGR color. + Args: + text (str): text to colorize. + color (str): ANSI SGR color code or color name defined in ANSIColor.COLORS. + + Returns: + colorized text + """ + if not any(c.isdigit() for c in color): + color = cls.COLORS.get(color.lower(), cls.COLORS["reset"]) -DEFAULT_LEVEL_COLORS = { - "DEBUG": ANSIColor.GREY, - "INFO": ANSIColor.GREY, - "WARNING": ANSIColor.YELLOW, - "ERROR": ANSIColor.RED, - "CRITICAL": ANSIColor.BOLD_RED, -} + return f"\x1b[{color}m{text}\x1b[{cls.COLORS['reset']}m" class BaseFormatter(logging.Formatter): def __init__(self, fmt="%(asctime)s - %(name)s - %(levelname)s - %(message)s", datefmt=None, style="%"): - """BaseFormatter is the default formatter for log records. + """Default formatter for log records. - Shortens logger %(name)s to the suffix, full name can be accessed with %(fullName)s + Shortens logger %(name)s to the basenames. Full name can be accessed with %(fullName)s Args: - fmt: format string which uses LogRecord attributes. - datefmt: date/time format string. Defaults to '%Y-%m-%d %H:%M:%S'. - style: style character '%' '{' or '$' for format string. + fmt (str): format string which uses LogRecord attributes. + datefmt (str): date/time format string. Defaults to '%Y-%m-%d %H:%M:%S'. + style (str): style character '%' '{' or '$' for format string. """ + self.fmt = fmt super().__init__(fmt=fmt, datefmt=datefmt, style=style) def format(self, record): @@ -61,9 +89,127 @@ def format(self, record): return super().format(record) -def ansi_sgr(code): - # ANSI Select Graphics Rendition - return "\x1b[" + code + "m" +class ColorFormatter(BaseFormatter): + def __init__( + self, + fmt="%(asctime)s - %(name)s - %(levelname)s - %(message)s", + datefmt=None, + style="%", + level_colors=ANSIColor.DEFAULT_LEVEL_COLORS, + logger_colors={}, + ): + """Format colors based on log levels. Optionally can provide mapping based on logger namess. + + Args: + fmt (str): format string which uses LogRecord attributes. + datefmt (str): date/time format string. Defaults to '%Y-%m-%d %H:%M:%S'. + style (str): style character '%' '{' or '$' for format string. + level_colors (Dict[str, str]): dict of levelname: ANSI color. Defaults to ANSIColor.DEFAULT_LEVEL_COLORS. + logger_colors (Dict[str, str]): dict of loggername: ANSI color. Defaults to {}. + + """ + super().__init__(fmt=fmt, datefmt=datefmt, style=style) + self.level_colors = level_colors + self.logger_colors = logger_colors + + def format(self, record): + super().format(record) + + # Apply level_colors based on record levelname + log_color = self.level_colors.get(record.levelname, "reset") + + # Apply logger_color to logger_names if INFO or below + if record.levelno <= logging.INFO: + log_color = self.logger_colors.get(record.name, log_color) + + log_fmt = ANSIColor.colorize(self.fmt, log_color) + + formatter = logging.Formatter(log_fmt) + return formatter.format(record) + + +class JsonFormatter(BaseFormatter): + def __init__( + self, + fmt="%(asctime)s - %(name)s - %(fullName)s - %(levelname)s - %(message)s", + datefmt=None, + style="%", + extract_brackets=True, + ): + """Format log records into JSON. + + Args: + fmt (str): format string which uses LogRecord attributes. Attributes are used for JSON keys. + datefmt (str): date/time format string. Defaults to '%Y-%m-%d %H:%M:%S'. + style (str): style character '%' '{' or '$' for format string. + extract_bracket_fields (bool): whether to extract bracket fields of message into sub-dictionary. Defaults to True. + + """ + super().__init__(fmt=fmt, datefmt=datefmt, style=style) + self.fmt_dict = self.generate_fmt_dict(self.fmt) + self.extract_brackets = extract_brackets + + def generate_fmt_dict(self, fmt: str) -> dict: + # Parse the `fmt` string and create a mapping of keys to LogRecord attributes + matches = re.findall(r"%\((.*?)\)([sd])", fmt) + + fmt_dict = {} + for key, _ in matches: + if key == "shortname": + fmt_dict["name"] = "shortname" + else: + fmt_dict[key] = key + + return fmt_dict + + def extract_bracket_fields(self, message: str) -> dict: + # Extract bracketed fl_ctx_fields eg. [k1=v1, k2=v2...] into sub-dictionary + bracket_fields = {} + match = re.search(r"\[(.*?)\]:", message) + if match: + pairs = match.group(1).split(", ") + for pair in pairs: + if "=" in pair: + key, value = pair.split("=", 1) + bracket_fields[key] = value + return bracket_fields + + def formatMessage(self, record) -> dict: + return {fmt_key: record.__dict__.get(fmt_val, "") for fmt_key, fmt_val in self.fmt_dict.items()} + + def format(self, record) -> str: + super().format(record) + + record.message = record.getMessage() + bracket_fields = self.extract_bracket_fields(record.message) if self.extract_brackets else None + record.asctime = self.formatTime(record) + + formatted_message_dict = self.formatMessage(record) + message_dict = {k: v for k, v in formatted_message_dict.items() if k != "message"} + + if bracket_fields: + message_dict["fl_ctx_fields"] = bracket_fields + record.message = re.sub(r"\[.*?\]:", "", record.message).strip() + + message_dict[self.fmt_dict.get("message", "message")] = record.message + + return json.dumps(message_dict, default=str) + + +class LoggerNameFilter(logging.Filter): + def __init__(self, logger_names=["nvflare"]): + """Filter log records based on logger names. + + Args: + logger_names (List[str]): list of logger names to allow through filter (inclusive) + + """ + super().__init__() + self.logger_names = logger_names + + def filter(self, record): + name = record.fullName if hasattr(record, "fullName") else record.name + return any(name.startswith(logger_name) for logger_name in self.logger_names) def get_module_logger(module=None, name=None): @@ -79,19 +225,41 @@ def get_obj_logger(obj): def get_script_logger(): + # Get script logger name based on filename and package. If not in a package, default to custom. caller_frame = inspect.stack()[1] package = caller_frame.frame.f_globals.get("__package__", "") file = caller_frame.frame.f_globals.get("__file__", "") return logging.getLogger( - f"{package + '.' if package else ''}{os.path.splitext(os.path.basename(file))[0] if file else ''}" + f"{package if package else 'custom'}{'.' + os.path.splitext(os.path.basename(file))[0] if file else ''}" ) -def configure_logging(workspace: Workspace): +def configure_logging(workspace: Workspace, dir_path: str = "", file_prefix: str = ""): + # Read log_config.json from workspace, update with file_prefix, and apply to dir_path log_config_file_path = workspace.get_log_config_file_path() assert os.path.isfile(log_config_file_path), f"missing log config file {log_config_file_path}" - logging.config.fileConfig(fname=log_config_file_path, disable_existing_loggers=False) + + with open(log_config_file_path, "r") as f: + dict_config = json.load(f) + + apply_log_config(dict_config, dir_path, file_prefix) + + +def apply_log_config(dict_config, dir_path: str = "", file_prefix: str = ""): + # Update log config dictionary with file_prefix, and apply to dir_path + stack = [dict_config] + while stack: + current_dict = stack.pop() + for key, value in current_dict.items(): + if isinstance(value, dict): + stack.append(value) + elif key == "filename": + if file_prefix: + value = os.path.join(os.path.dirname(value), file_prefix + "_" + os.path.basename(value)) + current_dict[key] = os.path.join(dir_path, value) + + logging.config.dictConfig(dict_config) def add_log_file_handler(log_file_name): @@ -103,7 +271,7 @@ def add_log_file_handler(log_file_name): root_logger.addHandler(file_handler) -def print_logger_hierarchy(package_name="nvflare", level_colors=DEFAULT_LEVEL_COLORS): +def print_logger_hierarchy(package_name="nvflare", level_colors=ANSIColor.DEFAULT_LEVEL_COLORS): all_loggers = logging.root.manager.loggerDict # Filter for package loggers based on package_name @@ -134,8 +302,8 @@ def print_hierarchy(logger_name, indent_level=0): level_display = f"{level_name} (SET)" if not is_unset else level_name # Print the logger with color and indentation - color = level_colors.get(level_name, ANSIColor.RESET) - print(" " * indent_level + f"{ansi_sgr(color)}{logger_name} [{level_display}]{ansi_sgr(ANSIColor.RESET)}") + color = level_colors.get(level_name, ANSIColor.COLORS["reset"]) + print(" " * indent_level + ANSIColor.colorize(f"{logger_name} [{level_display}]", color)) # Find child loggers based on the current hierarchy level for name in sorted_package_loggers: diff --git a/nvflare/lighter/constants.py b/nvflare/lighter/constants.py index 97b18d0595..a6341d3abb 100644 --- a/nvflare/lighter/constants.py +++ b/nvflare/lighter/constants.py @@ -115,7 +115,7 @@ class ProvFileName: FED_SERVER_JSON = "fed_server.json" FED_CLIENT_JSON = "fed_client.json" STOP_FL_SH = "stop_fl.sh" - LOG_CONFIG_DEFAULT = "log.config.default" + LOG_CONFIG_DEFAULT = "log_config.json.default" RESOURCES_JSON_DEFAULT = "resources.json.default" PRIVACY_JSON_SAMPLE = "privacy.json.sample" AUTHORIZATION_JSON_DEFAULT = "authorization.json.default" diff --git a/nvflare/lighter/impl/master_template.yml b/nvflare/lighter/impl/master_template.yml index 09ee86230e..68961077d2 100644 --- a/nvflare/lighter/impl/master_template.yml +++ b/nvflare/lighter/impl/master_template.yml @@ -303,34 +303,83 @@ fl_admin_sh: | python3 -m nvflare.fuel.hci.tools.admin -m $DIR/.. -s fed_admin.json log_config: | - [loggers] - keys=root - - [handlers] - keys=consoleHandler,errorFileHandler - - [formatters] - keys=baseFormatter - - [logger_root] - level=INFO - handlers=consoleHandler,errorFileHandler - - [handler_consoleHandler] - class=StreamHandler - level=DEBUG - formatter=baseFormatter - args=(sys.stdout,) - - [handler_errorFileHandler] - class=FileHandler - level=ERROR - formatter=baseFormatter - args=('error_log.txt', 'a') - - [formatter_baseFormatter] - class=nvflare.fuel.utils.log_utils.BaseFormatter - format=%(asctime)s - %(name)s - %(levelname)s - %(message)s + { + "version": 1, + "disable_existing_loggers": false, + "formatters": { + "baseFormatter": { + "()": "nvflare.fuel.utils.log_utils.BaseFormatter", + "fmt": "%(asctime)s - %(name)s - %(levelname)s - %(message)s" + }, + "colorFormatter": { + "()": "nvflare.fuel.utils.log_utils.ColorFormatter", + "fmt": "%(asctime)s - %(name)s - %(levelname)s - %(message)s" + }, + "jsonFormatter": { + "()": "nvflare.fuel.utils.log_utils.JsonFormatter", + "fmt": "%(asctime)s - %(name)s - %(fullName)s - %(levelname)s - %(message)s" + } + }, + "filters": { + "FLFilter": { + "()": "nvflare.fuel.utils.log_utils.LoggerNameFilter", + "logger_names": ["custom", "nvflare.app_common", "nvflare.app_opt"] + } + }, + "handlers": { + "consoleHandler": { + "class": "logging.StreamHandler", + "level": "DEBUG", + "formatter": "colorFormatter", + "filters": [], + "stream": "ext://sys.stdout" + }, + "logFileHandler": { + "class": "logging.handlers.RotatingFileHandler", + "level": "DEBUG", + "formatter": "baseFormatter", + "filename": "log.txt", + "mode": "a", + "maxBytes": 20971520, + "backupCount": 10 + }, + "errorFileHandler": { + "class": "logging.handlers.RotatingFileHandler", + "level": "ERROR", + "formatter": "baseFormatter", + "filename": "log_error.txt", + "mode": "a", + "maxBytes": 20971520, + "backupCount": 10 + }, + "jsonFileHandler": { + "class": "logging.handlers.RotatingFileHandler", + "level": "DEBUG", + "formatter": "jsonFormatter", + "filename": "log.json", + "mode": "a", + "maxBytes": 20971520, + "backupCount": 10 + }, + "FLFileHandler": { + "class": "logging.handlers.RotatingFileHandler", + "level": "DEBUG", + "formatter": "baseFormatter", + "filters": ["FLFilter"], + "filename": "log_fl.txt", + "mode": "a", + "maxBytes": 20971520, + "backupCount": 10, + "delay": true + } + }, + "loggers": { + "root": { + "level": "INFO", + "handlers": ["consoleHandler", "logFileHandler", "errorFileHandler", "jsonFileHandler", "FLFileHandler"] + } + } + } start_ovsr_sh: | #!/usr/bin/env bash diff --git a/nvflare/lighter/templates/master_template.yml b/nvflare/lighter/templates/master_template.yml index 7b1e51af88..68961077d2 100644 --- a/nvflare/lighter/templates/master_template.yml +++ b/nvflare/lighter/templates/master_template.yml @@ -303,33 +303,83 @@ fl_admin_sh: | python3 -m nvflare.fuel.hci.tools.admin -m $DIR/.. -s fed_admin.json log_config: | - [loggers] - keys=root - - [handlers] - keys=consoleHandler,errorFileHandler - - [formatters] - keys=fullFormatter - - [logger_root] - level=INFO - handlers=consoleHandler,errorFileHandler - - [handler_consoleHandler] - class=StreamHandler - level=DEBUG - formatter=fullFormatter - args=(sys.stdout,) - - [handler_errorFileHandler] - class=FileHandler - level=ERROR - formatter=fullFormatter - args=('error.log', 'a') - - [formatter_fullFormatter] - format=%(asctime)s - %(name)s - %(levelname)s - %(message)s + { + "version": 1, + "disable_existing_loggers": false, + "formatters": { + "baseFormatter": { + "()": "nvflare.fuel.utils.log_utils.BaseFormatter", + "fmt": "%(asctime)s - %(name)s - %(levelname)s - %(message)s" + }, + "colorFormatter": { + "()": "nvflare.fuel.utils.log_utils.ColorFormatter", + "fmt": "%(asctime)s - %(name)s - %(levelname)s - %(message)s" + }, + "jsonFormatter": { + "()": "nvflare.fuel.utils.log_utils.JsonFormatter", + "fmt": "%(asctime)s - %(name)s - %(fullName)s - %(levelname)s - %(message)s" + } + }, + "filters": { + "FLFilter": { + "()": "nvflare.fuel.utils.log_utils.LoggerNameFilter", + "logger_names": ["custom", "nvflare.app_common", "nvflare.app_opt"] + } + }, + "handlers": { + "consoleHandler": { + "class": "logging.StreamHandler", + "level": "DEBUG", + "formatter": "colorFormatter", + "filters": [], + "stream": "ext://sys.stdout" + }, + "logFileHandler": { + "class": "logging.handlers.RotatingFileHandler", + "level": "DEBUG", + "formatter": "baseFormatter", + "filename": "log.txt", + "mode": "a", + "maxBytes": 20971520, + "backupCount": 10 + }, + "errorFileHandler": { + "class": "logging.handlers.RotatingFileHandler", + "level": "ERROR", + "formatter": "baseFormatter", + "filename": "log_error.txt", + "mode": "a", + "maxBytes": 20971520, + "backupCount": 10 + }, + "jsonFileHandler": { + "class": "logging.handlers.RotatingFileHandler", + "level": "DEBUG", + "formatter": "jsonFormatter", + "filename": "log.json", + "mode": "a", + "maxBytes": 20971520, + "backupCount": 10 + }, + "FLFileHandler": { + "class": "logging.handlers.RotatingFileHandler", + "level": "DEBUG", + "formatter": "baseFormatter", + "filters": ["FLFilter"], + "filename": "log_fl.txt", + "mode": "a", + "maxBytes": 20971520, + "backupCount": 10, + "delay": true + } + }, + "loggers": { + "root": { + "level": "INFO", + "handlers": ["consoleHandler", "logFileHandler", "errorFileHandler", "jsonFileHandler", "FLFileHandler"] + } + } + } start_ovsr_sh: | #!/usr/bin/env bash diff --git a/nvflare/lighter/utils.py b/nvflare/lighter/utils.py index 2c26d9f016..ae71e409fa 100644 --- a/nvflare/lighter/utils.py +++ b/nvflare/lighter/utils.py @@ -322,7 +322,7 @@ def _write_common(type, dest_dir, template, tplt, replacement_dict, config): def _write_local(type, dest_dir, template, capacity=""): write( - os.path.join(dest_dir, "log.config.default"), + os.path.join(dest_dir, "log_config.json.default"), template["log_config"], "t", ) diff --git a/nvflare/private/fed/app/client/client_train.py b/nvflare/private/fed/app/client/client_train.py index 544567e0c5..235631c978 100644 --- a/nvflare/private/fed/app/client/client_train.py +++ b/nvflare/private/fed/app/client/client_train.py @@ -25,6 +25,7 @@ from nvflare.fuel.common.excepts import ConfigError from nvflare.fuel.f3.mpm import MainProcessMonitor as mpm from nvflare.fuel.utils.argument_utils import parse_vars +from nvflare.fuel.utils.log_utils import configure_logging from nvflare.private.defs import AppFolderConstants from nvflare.private.fed.app.fl_conf import FLClientStarterConfiger, create_privacy_manager from nvflare.private.fed.app.utils import component_security_check, version_check @@ -32,7 +33,7 @@ from nvflare.private.fed.client.client_engine import ClientEngine from nvflare.private.fed.client.client_status import ClientStatus from nvflare.private.fed.client.fed_client import FederatedClient -from nvflare.private.fed.utils.fed_utils import add_logfile_handler, fobs_initialize, security_init +from nvflare.private.fed.utils.fed_utils import fobs_initialize, security_init from nvflare.private.privacy_manager import PrivacyService from nvflare.security.logging import secure_format_exception @@ -75,8 +76,7 @@ def main(args): ) conf.configure() - log_file = workspace.get_log_file_path() - add_logfile_handler(log_file) + configure_logging(workspace, workspace.get_root_dir()) deployer = conf.base_deployer security_init( diff --git a/nvflare/private/fed/app/client/sub_worker_process.py b/nvflare/private/fed/app/client/sub_worker_process.py index bd2ce4cf8d..321fe3e71b 100644 --- a/nvflare/private/fed/app/client/sub_worker_process.py +++ b/nvflare/private/fed/app/client/sub_worker_process.py @@ -43,7 +43,7 @@ from nvflare.fuel.f3.mpm import MainProcessMonitor as mpm from nvflare.fuel.sec.audit import AuditService from nvflare.fuel.sec.security_content_service import SecurityContentService -from nvflare.fuel.utils.log_utils import get_obj_logger, get_script_logger +from nvflare.fuel.utils.log_utils import configure_logging, get_obj_logger, get_script_logger from nvflare.private.defs import CellChannel, CellChannelTopic, new_cell_message from nvflare.private.fed.app.fl_conf import create_privacy_manager from nvflare.private.fed.app.utils import monitor_parent_process @@ -51,8 +51,6 @@ from nvflare.private.fed.runner import Runner from nvflare.private.fed.simulator.simulator_app_runner import SimulatorClientRunManager from nvflare.private.fed.utils.fed_utils import ( - add_logfile_handler, - configure_logging, create_stats_pool_files_for_job, fobs_initialize, register_ext_decomposers, @@ -309,7 +307,7 @@ def stop(self): def main(args): workspace = Workspace(args.workspace, args.client_name) - configure_logging(workspace) + configure_logging(workspace, workspace.get_run_dir(args.job_id)) fobs_initialize(workspace=workspace, job_id=args.job_id) register_ext_decomposers(args.decomposer_module) @@ -339,8 +337,6 @@ def main(args): thread.start() job_id = args.job_id - log_file = workspace.get_app_log_file_path(job_id) - add_logfile_handler(log_file) logger = get_script_logger() sub_executor.run() diff --git a/nvflare/private/fed/app/client/worker_process.py b/nvflare/private/fed/app/client/worker_process.py index e438e8e8f1..2f4da3db9e 100644 --- a/nvflare/private/fed/app/client/worker_process.py +++ b/nvflare/private/fed/app/client/worker_process.py @@ -25,14 +25,13 @@ from nvflare.fuel.f3.mpm import MainProcessMonitor as mpm from nvflare.fuel.utils.argument_utils import parse_vars from nvflare.fuel.utils.config_service import ConfigService -from nvflare.fuel.utils.log_utils import get_script_logger +from nvflare.fuel.utils.log_utils import configure_logging, get_script_logger from nvflare.private.defs import EngineConstant from nvflare.private.fed.app.fl_conf import FLClientStarterConfiger from nvflare.private.fed.app.utils import monitor_parent_process from nvflare.private.fed.client.client_app_runner import ClientAppRunner from nvflare.private.fed.client.client_status import ClientStatus from nvflare.private.fed.utils.fed_utils import ( - add_logfile_handler, create_stats_pool_files_for_job, fobs_initialize, register_ext_decomposers, @@ -98,8 +97,7 @@ def main(args): ) register_ext_decomposers(decomposer_module) - log_file = workspace.get_app_log_file_path(args.job_id) - add_logfile_handler(log_file) + configure_logging(workspace, workspace.get_run_dir(args.job_id)) logger = get_script_logger() logger.info("Worker_process started.") diff --git a/nvflare/private/fed/app/fl_conf.py b/nvflare/private/fed/app/fl_conf.py index 084bb90248..7a60876637 100644 --- a/nvflare/private/fed/app/fl_conf.py +++ b/nvflare/private/fed/app/fl_conf.py @@ -26,7 +26,6 @@ from nvflare.fuel.utils.json_scanner import Node from nvflare.fuel.utils.wfconf import ConfigContext, ConfigError from nvflare.private.defs import SSLConstants -from nvflare.private.fed.utils.fed_utils import configure_logging from nvflare.private.json_configer import JsonConfigurator from nvflare.private.privacy_manager import PrivacyManager, Scope @@ -63,8 +62,6 @@ def __init__(self, workspace: Workspace, args, kv_list=None): else: self.cmd_vars = {} - configure_logging(workspace) - config_files = workspace.get_config_files_for_startup(is_server=True, for_job=True if args.job_id else False) JsonConfigurator.__init__( @@ -226,8 +223,6 @@ def __init__(self, workspace: Workspace, args, kv_list=None): else: self.cmd_vars = {} - configure_logging(workspace) - config_files = workspace.get_config_files_for_startup(is_server=False, for_job=True if args.job_id else False) JsonConfigurator.__init__( diff --git a/nvflare/private/fed/app/server/runner_process.py b/nvflare/private/fed/app/server/runner_process.py index 76dbf73f01..0777152be2 100644 --- a/nvflare/private/fed/app/server/runner_process.py +++ b/nvflare/private/fed/app/server/runner_process.py @@ -26,14 +26,13 @@ from nvflare.fuel.f3.mpm import MainProcessMonitor as mpm from nvflare.fuel.utils.argument_utils import parse_vars from nvflare.fuel.utils.config_service import ConfigService -from nvflare.fuel.utils.log_utils import get_script_logger +from nvflare.fuel.utils.log_utils import configure_logging, get_script_logger from nvflare.private.defs import AppFolderConstants from nvflare.private.fed.app.fl_conf import FLServerStarterConfiger from nvflare.private.fed.app.utils import monitor_parent_process from nvflare.private.fed.server.server_app_runner import ServerAppRunner from nvflare.private.fed.server.server_state import HotState from nvflare.private.fed.utils.fed_utils import ( - add_logfile_handler, create_stats_pool_files_for_job, fobs_initialize, register_ext_decomposers, @@ -78,8 +77,7 @@ def main(args): args=args, kv_list=args.set, ) - log_file = workspace.get_app_log_file_path(args.job_id) - add_logfile_handler(log_file) + configure_logging(workspace, workspace.get_run_dir(args.job_id)) logger = get_script_logger() logger.info("Runner_process started.") diff --git a/nvflare/private/fed/app/server/server_train.py b/nvflare/private/fed/app/server/server_train.py index 00cf7e121a..2fa79d1513 100644 --- a/nvflare/private/fed/app/server/server_train.py +++ b/nvflare/private/fed/app/server/server_train.py @@ -25,11 +25,12 @@ from nvflare.fuel.common.excepts import ConfigError from nvflare.fuel.f3.mpm import MainProcessMonitor as mpm from nvflare.fuel.utils.argument_utils import parse_vars +from nvflare.fuel.utils.log_utils import configure_logging from nvflare.private.defs import AppFolderConstants from nvflare.private.fed.app.fl_conf import FLServerStarterConfiger, create_privacy_manager from nvflare.private.fed.app.utils import create_admin_server, version_check from nvflare.private.fed.server.server_status import ServerStatus -from nvflare.private.fed.utils.fed_utils import add_logfile_handler, fobs_initialize, security_init +from nvflare.private.fed.utils.fed_utils import fobs_initialize, security_init from nvflare.private.privacy_manager import PrivacyService from nvflare.security.logging import secure_format_exception @@ -83,8 +84,7 @@ def main(args): logger.critical("loglevel critical enabled") conf.configure() - log_file = workspace.get_log_file_path() - add_logfile_handler(log_file) + configure_logging(workspace, workspace.get_root_dir()) deployer = conf.deployer secure_train = conf.cmd_vars.get("secure_train", False) diff --git a/nvflare/private/fed/app/simulator/log.config b/nvflare/private/fed/app/simulator/log.config deleted file mode 100644 index 07c2963686..0000000000 --- a/nvflare/private/fed/app/simulator/log.config +++ /dev/null @@ -1,28 +0,0 @@ -[loggers] -keys=root - -[handlers] -keys=consoleHandler,errorFileHandler - -[formatters] -keys=baseFormatter - -[logger_root] -level=INFO -handlers=consoleHandler,errorFileHandler - -[handler_consoleHandler] -class=StreamHandler -level=DEBUG -formatter=baseFormatter -args=(sys.stdout,) - -[handler_errorFileHandler] -class=FileHandler -level=ERROR -formatter=baseFormatter -args=('error_log.txt', 'a') - -[formatter_baseFormatter] -class=nvflare.fuel.utils.log_utils.BaseFormatter -format=%(asctime)s - %(name)s - %(levelname)s - %(message)s \ No newline at end of file diff --git a/nvflare/private/fed/app/simulator/log_config.json b/nvflare/private/fed/app/simulator/log_config.json new file mode 100644 index 0000000000..a245312cf7 --- /dev/null +++ b/nvflare/private/fed/app/simulator/log_config.json @@ -0,0 +1,77 @@ +{ + "version": 1, + "disable_existing_loggers": false, + "formatters": { + "baseFormatter": { + "()": "nvflare.fuel.utils.log_utils.BaseFormatter", + "fmt": "%(asctime)s - %(name)s - %(levelname)s - %(message)s" + }, + "colorFormatter": { + "()": "nvflare.fuel.utils.log_utils.ColorFormatter", + "fmt": "%(asctime)s - %(name)s - %(levelname)s - %(message)s" + }, + "jsonFormatter": { + "()": "nvflare.fuel.utils.log_utils.JsonFormatter", + "fmt": "%(asctime)s - %(name)s - %(fullName)s - %(levelname)s - %(message)s" + } + }, + "filters": { + "FLFilter": { + "()": "nvflare.fuel.utils.log_utils.LoggerNameFilter", + "logger_names": ["custom", "nvflare.app_common", "nvflare.app_opt"] + } + }, + "handlers": { + "consoleHandler": { + "class": "logging.StreamHandler", + "level": "DEBUG", + "formatter": "colorFormatter", + "filters": [], + "stream": "ext://sys.stdout" + }, + "logFileHandler": { + "class": "logging.handlers.RotatingFileHandler", + "level": "DEBUG", + "formatter": "baseFormatter", + "filename": "log.txt", + "mode": "a", + "maxBytes": 20971520, + "backupCount": 10 + }, + "errorFileHandler": { + "class": "logging.handlers.RotatingFileHandler", + "level": "ERROR", + "formatter": "baseFormatter", + "filename": "log_error.txt", + "mode": "a", + "maxBytes": 20971520, + "backupCount": 10 + }, + "jsonFileHandler": { + "class": "logging.handlers.RotatingFileHandler", + "level": "DEBUG", + "formatter": "jsonFormatter", + "filename": "log.json", + "mode": "a", + "maxBytes": 20971520, + "backupCount": 10 + }, + "FLFileHandler": { + "class": "logging.handlers.RotatingFileHandler", + "level": "DEBUG", + "formatter": "baseFormatter", + "filters": ["FLFilter"], + "filename": "log_fl.txt", + "mode": "a", + "maxBytes": 20971520, + "backupCount": 10, + "delay": true + } + }, + "loggers": { + "root": { + "level": "INFO", + "handlers": ["consoleHandler", "logFileHandler", "errorFileHandler", "jsonFileHandler", "FLFileHandler"] + } + } +} \ No newline at end of file diff --git a/nvflare/private/fed/app/simulator/simulator_runner.py b/nvflare/private/fed/app/simulator/simulator_runner.py index c22e45327c..4896647265 100644 --- a/nvflare/private/fed/app/simulator/simulator_runner.py +++ b/nvflare/private/fed/app/simulator/simulator_runner.py @@ -13,7 +13,6 @@ # limitations under the License. import copy import json -import logging.config import os import shlex import shutil @@ -53,6 +52,7 @@ from nvflare.fuel.utils.argument_utils import parse_vars from nvflare.fuel.utils.config_service import ConfigService from nvflare.fuel.utils.gpu_utils import get_host_gpu_ids +from nvflare.fuel.utils.log_utils import apply_log_config from nvflare.fuel.utils.network_utils import get_open_ports from nvflare.fuel.utils.zip_utils import split_path, unzip_all_from_bytes, zip_directory_to_bytes from nvflare.private.defs import AppFolderConstants @@ -64,7 +64,6 @@ from nvflare.private.fed.simulator.simulator_audit import SimulatorAuditor from nvflare.private.fed.simulator.simulator_const import SimulatorConstants from nvflare.private.fed.utils.fed_utils import ( - add_logfile_handler, custom_fobs_initialize, get_simulator_app_root, nvflare_fobs_initialize, @@ -156,7 +155,9 @@ def setup(self): log_config_file_path = os.path.join(self.args.workspace, "local", WorkspaceConstants.LOGGING_CONFIG) if not os.path.isfile(log_config_file_path): log_config_file_path = os.path.join(os.path.dirname(__file__), WorkspaceConstants.LOGGING_CONFIG) - logging.config.fileConfig(fname=log_config_file_path, disable_existing_loggers=False) + + with open(log_config_file_path, "r") as f: + dict_config = json.load(f) self.args.log_config = None self.args.config_folder = "config" @@ -179,8 +180,8 @@ def setup(self): init_security_content_service(self.args.workspace) os.makedirs(os.path.join(self.simulator_root, SiteType.SERVER)) - log_file = os.path.join(self.simulator_root, SiteType.SERVER, WorkspaceConstants.LOG_FILE_NAME) - add_logfile_handler(log_file) + + apply_log_config(dict_config, os.path.join(self.simulator_root, SiteType.SERVER)) try: data_bytes, job_name, meta = self.validate_job_data() diff --git a/nvflare/private/fed/app/simulator/simulator_worker.py b/nvflare/private/fed/app/simulator/simulator_worker.py index 262f78026f..baae171ce9 100644 --- a/nvflare/private/fed/app/simulator/simulator_worker.py +++ b/nvflare/private/fed/app/simulator/simulator_worker.py @@ -13,7 +13,7 @@ # limitations under the License. import argparse -import logging.config +import json import os import sys import threading @@ -30,6 +30,7 @@ from nvflare.fuel.f3.mpm import MainProcessMonitor as mpm from nvflare.fuel.hci.server.authz import AuthorizationService from nvflare.fuel.sec.audit import AuditService +from nvflare.fuel.utils.log_utils import apply_log_config from nvflare.private.fed.app.deployer.base_client_deployer import BaseClientDeployer from nvflare.private.fed.app.utils import check_parent_alive, init_security_content_service from nvflare.private.fed.client.client_engine import ClientEngine @@ -38,12 +39,7 @@ from nvflare.private.fed.simulator.simulator_app_runner import SimulatorClientAppRunner from nvflare.private.fed.simulator.simulator_audit import SimulatorAuditor from nvflare.private.fed.simulator.simulator_const import SimulatorConstants -from nvflare.private.fed.utils.fed_utils import ( - add_logfile_handler, - fobs_initialize, - get_simulator_app_root, - register_ext_decomposers, -) +from nvflare.private.fed.utils.fed_utils import fobs_initialize, get_simulator_app_root, register_ext_decomposers from nvflare.security.logging import secure_format_exception, secure_log_traceback from nvflare.security.security import EmptyAuthorizer @@ -238,9 +234,10 @@ def main(args): thread = threading.Thread(target=check_parent_alive, args=(parent_pid, stop_event)) thread.start() - logging.config.fileConfig(fname=args.logging_config, disable_existing_loggers=False) - log_file = os.path.join(args.workspace, WorkspaceConstants.LOG_FILE_NAME) - add_logfile_handler(log_file) + with open(args.logging_config, "r") as f: + dict_config = json.load(f) + + apply_log_config(dict_config, args.workspace) os.chdir(args.workspace) startup = os.path.join(args.workspace, WorkspaceConstants.STARTUP_FOLDER_NAME) diff --git a/nvflare/private/fed/utils/fed_utils.py b/nvflare/private/fed/utils/fed_utils.py index be8d27d757..5b84f55909 100644 --- a/nvflare/private/fed/utils/fed_utils.py +++ b/nvflare/private/fed/utils/fed_utils.py @@ -13,13 +13,10 @@ # limitations under the License. import importlib import json -import logging -import logging.config import os import pkgutil import sys import warnings -from logging.handlers import RotatingFileHandler from typing import Any, List, Union from nvflare.apis.app_validation import AppValidator @@ -52,46 +49,6 @@ from .app_authz import AppAuthzService -def add_logfile_handler(log_file: str): - """Adds a log file handler to the root logger. - - The purpose for this is to handle dynamic log file locations. - - If a handler named errorFileHandler is found, it will be used as a template to - create a new handler for writing to the error log file at the same directory as log_file. - The original errorFileHandler will be removed and replaced by the new handler. - - Each log file will be rotated when it reaches 20MB. - - Args: - log_file (str): log file path - """ - root_logger = logging.getLogger() - configured_handlers = root_logger.handlers - main_handler = root_logger.handlers[0] - file_handler = RotatingFileHandler(log_file, maxBytes=20 * 1024 * 1024, backupCount=10) - file_handler.setLevel(main_handler.level) - file_handler.setFormatter(main_handler.formatter) - root_logger.addHandler(file_handler) - - configured_error_handler = None - for handler in configured_handlers: - if handler.get_name() == "errorFileHandler": - configured_error_handler = handler - break - - if not configured_error_handler: - return - - error_log_file = os.path.join(os.path.dirname(log_file), WorkspaceConstants.ERROR_LOG_FILE_NAME) - error_file_handler = RotatingFileHandler(error_log_file, maxBytes=20 * 1024 * 1024, backupCount=10) - error_file_handler.setLevel(configured_error_handler.level) - error_file_handler.setFormatter(configured_error_handler.formatter) - - root_logger.addHandler(error_file_handler) - root_logger.removeHandler(configured_error_handler) - - def _check_secure_content(site_type: str) -> List[str]: """To check the security contents. @@ -253,12 +210,6 @@ def find_char_positions(s, ch): return [i for i, c in enumerate(s) if c == ch] -def configure_logging(workspace: Workspace): - log_config_file_path = workspace.get_log_config_file_path() - assert os.path.isfile(log_config_file_path), f"missing log config file {log_config_file_path}" - logging.config.fileConfig(fname=log_config_file_path, disable_existing_loggers=False) - - def get_scope_info(): try: privacy_manager = PrivacyService.get_manager()