From 64ca43847ba9ba89ed852dc36615ca66b4f8f5bc Mon Sep 17 00:00:00 2001 From: Keith Suderman Date: Wed, 20 Nov 2024 14:48:37 -0500 Subject: [PATCH 1/6] Changess for trace() logging enhancements --- lib/galaxy/app.py | 8 + lib/galaxy/config/__init__.py | 11 +- lib/galaxy/queue_worker.py | 12 ++ lib/galaxy/util/logging/__init__.py | 219 +++++++++++++++++++++++ lib/galaxy/webapps/galaxy/api/logging.py | 43 +++++ lib/galaxy_test/api/test_logging.py | 150 ++++++++++++++++ test/unit/util/test_logging.py | 135 ++++++++++++++ 7 files changed, 576 insertions(+), 2 deletions(-) create mode 100644 lib/galaxy/util/logging/__init__.py create mode 100644 lib/galaxy/webapps/galaxy/api/logging.py create mode 100644 lib/galaxy_test/api/test_logging.py create mode 100644 test/unit/util/test_logging.py diff --git a/lib/galaxy/app.py b/lib/galaxy/app.py index 285e2eed8a1c..87c5d9130372 100644 --- a/lib/galaxy/app.py +++ b/lib/galaxy/app.py @@ -1,6 +1,14 @@ import collections import errno import logging + +# This needs to be done before any other galaxy imports to ensure all logging is +# captured. There is no harm in calling addTraceLoggingLevel multiple times, but +# it is only needed once provided we do it early enough in the code loading +# process. +from galaxy.util.logging import addTraceLoggingLevel +addTraceLoggingLevel() + import os import signal import sys diff --git a/lib/galaxy/config/__init__.py b/lib/galaxy/config/__init__.py index d253b3d0d9b6..c1bbf5799438 100644 --- a/lib/galaxy/config/__init__.py +++ b/lib/galaxy/config/__init__.py @@ -55,6 +55,7 @@ resource_path, ) from galaxy.util.themes import flatten_theme +from ..util.logging import set_logging_levels_from_config from ..version import ( VERSION_MAJOR, VERSION_MINOR, @@ -167,8 +168,7 @@ def configure_logging(config, facts=None): or a simple dictionary of configuration variables. """ facts = facts or get_facts(config=config) - # Get root logger - logging.addLevelName(LOGLV_TRACE, "TRACE") + # PasteScript will have already configured the logger if the # 'loggers' section was found in the config file, otherwise we do # some simple setup using the 'log_*' values from the config. @@ -197,6 +197,10 @@ def configure_logging(config, facts=None): conf["filename"] = conf.pop("filename_template").format(**facts) logging_conf["handlers"][name] = conf logging.config.dictConfig(logging_conf) + logging_levels = config.get("logging_levels", None) + if logging_levels: + set_logging_levels_from_config(logging_levels) + def find_root(kwargs) -> str: @@ -540,6 +544,9 @@ def resolve(key): def _check_against_root(self, key): def get_path(current_path, initial_path): + # TODO: Not sure why this is needed for the logging API tests... + if initial_path is None: + return current_path # if path does not exist and was set as relative: if not self._path_exists(current_path) and not os.path.isabs(initial_path): new_path = self._in_root_dir(initial_path) diff --git a/lib/galaxy/queue_worker.py b/lib/galaxy/queue_worker.py index 3d80addf28dd..e81876ce11d5 100644 --- a/lib/galaxy/queue_worker.py +++ b/lib/galaxy/queue_worker.py @@ -27,6 +27,7 @@ from galaxy.tools import ToolBox from galaxy.tools.data_manager.manager import DataManagers from galaxy.tools.special_tools import load_lib_tools +from galaxy.util.logging import set_log_levels logging.getLogger("kombu").setLevel(logging.WARNING) log = logging.getLogger(__name__) @@ -299,6 +300,16 @@ def admin_job_lock(app, **kwargs): log.info(f"Administrative Job Lock is now set to {job_lock}. Jobs will {'not' if job_lock else 'now'} dispatch.") +def set_logging_levels(app, **kwargs): + """ + Set levels for loggers. + """ + name = kwargs.get("name") + level = kwargs.get("level") + log.debug("Setting logging levels for %s to %s.", name, level) + set_log_levels(name, level) + + control_message_to_task = { "create_panel_section": create_panel_section, "reload_tool": reload_tool, @@ -314,6 +325,7 @@ def admin_job_lock(app, **kwargs): "reconfigure_watcher": reconfigure_watcher, "reload_tour": reload_tour, "reload_core_config": reload_core_config, + "set_logging_levels": set_logging_levels } diff --git a/lib/galaxy/util/logging/__init__.py b/lib/galaxy/util/logging/__init__.py new file mode 100644 index 000000000000..9f5b02e84c6a --- /dev/null +++ b/lib/galaxy/util/logging/__init__.py @@ -0,0 +1,219 @@ +import logging +from typing import List, Dict + + +TRACE = logging.DEBUG - 5 + +log = logging.getLogger(__name__) + + +def addTraceLoggingLevel(): + addLoggingLevel('TRACE', TRACE) + + +def set_logging_levels_from_config(configuration: dict): + all_logger_names = logging.Logger.manager.loggerDict.keys() + settings = dict() + for name,level in configuration.items(): + if type(level) == int: + level = logging.getLevelName(level) + else: + level = level.upper() + if name.endswith(".*"): + pattern = name[:-2] + for name in all_logger_names: + if name.startswith(pattern): + settings[name] = level + else: + settings[name] = level + for name,level in settings.items(): + logging.getLogger(name).setLevel(level) + + +def _get_level_info(logger) -> Dict[str, str]: + ''' + Get the level and effective level of a logger + + :param logger: The logger to get the info for + :type logger: logging.Logger + + :return: The level and effective level of the logger + :rtype: Dict[str, str] + ''' + if logger is None: + return { + "name": "None", + "level": "NOTSET", + "effective": "NOTSET" + } + return { + "name": logger.name, + "level": logging.getLevelName(logger.level), + "effective": logging.getLevelName(logger.getEffectiveLevel()) + } + + +def get_logger_names() -> List[str]: + ''' + Gets the names of all the currently configured loggers. + + :return: The names of all the currently configured loggers + :rtype: List[str] + ''' + log.info("Getting a list of all configured loggers") + logger_dict = logging.Logger.manager.loggerDict + loggers = [name for name in logger_dict if isinstance(logger_dict[name], logging.Logger)] + return loggers + + + +def get_log_levels(name) -> Dict[str, Dict[str, str]]: + ''' + Get the log level for a one or more loggers. If no name is provided then + the levels for all loggers is returned. + + :param name: The name of the logger to get the level for + :type name: str + + :return: The log level for the logger + :rtype: Dict[str, Dict[str, str]] + ''' + # if not trans.user_is_admin: + # log.warning("Only admins can get log level") + # raise AdminRequiredException() + log.info("Getting level for logger %s", name) + loggers = get_logger_names() + if name is None: + result = {} + for logger_name in loggers: + logger = logging.getLogger(logger_name) + result[logger_name] = _get_level_info(logger) + return result + elif name.endswith(".*"): + result = {} + pattern = name[:-2] + for logger_name in [logger for logger in loggers if logger.startswith(pattern)]: + logger = logging.getLogger(logger_name) + result[logger_name] = _get_level_info(logger) + return result + elif name in loggers: + logger = logging.getLogger(name) + return { name: _get_level_info(logger) } + log.warning("Logger %s not found", name) + return { "UNKNOWN": _get_level_info(None) } + + +def set_log_levels(name, level) -> List[Dict[str,str]]: + ''' + Set the log level for a one or more loggers. + + To set the level for a single logger, pass the name of the logger. To set + the level for all loggers that start with a certain prefix, e.g. all the logger + in a particular package, pass the prefix followed by ".*". + + + :param name: The name of the logger(s) to set the level for + :type name: str + :param level: The level to set the logger to + :type level: str + + :return: The log level for the logger + :rtype: LoggerLevelInfo + ''' + # if not trans.user_is_admin: + # log.warning("Only admins can set log level") + # raise AdminRequiredException() + log.info("Setting level for logger %s to %s", name, level) + result = [] + loggers = get_logger_names() + if name.endswith(".*"): + pattern = name[:-2] + for logger_name in [logger for logger in loggers if logger.startswith(pattern)]: + logger = logging.getLogger(logger_name) + logger.setLevel(level) + result.append(_get_level_info(logger)) + return result + elif name in loggers: + logger = logging.getLogger(name) + logger.setLevel(level) + result.append(_get_level_info(logger)) + else: + log.warning("Logger %s not found", name) + return result + + +def addLoggingLevel(levelName, levelNum, methodName=None): + """ + A modified version of the method found at + https://stackoverflow.com/a/35804945/1691778 + + Rather than raising an AttributeError we simply return if the levelName or + methodName already exist. + + --- Original Docstring --- + + Comprehensively adds a new logging level to the `logging` module and the + currently configured logging class. + + `levelName` becomes an attribute of the `logging` module with the value + `levelNum`. `methodName` becomes a convenience method for both `logging` + itself and the class returned by `logging.getLoggerClass()` (usually just + `logging.Logger`). If `methodName` is not specified, `levelName.lower()` is + used. + + This method was inspired by the answers to Stack Overflow post + http://stackoverflow.com/q/2183233/2988730, especially + http://stackoverflow.com/a/13638084/2988730 + + Example + ------- + >>> addLoggingLevel('TRACE', logging.DEBUG - 5) + >>> logging.getLogger(__name__).setLevel("TRACE") + >>> logging.getLogger(__name__).trace('that worked') + >>> logging.trace('so did this') + >>> logging.TRACE + 5 + + """ + if not methodName: + methodName = levelName.lower() + + if hasattr(logging, levelName) or hasattr(logging, methodName) or hasattr(logging.getLoggerClass(), methodName): + logging.warning("Attempted to add logging level %s with level number %d and method name %s, but one or more already exist", levelName, levelNum, methodName) + # traceback.print_stack() + return + + # TDOD: Do we really want to do this here? + logging.basicConfig(level=logging.DEBUG, + format='%(asctime)s [%(levelname)s] %(name)s %(filename)s:%(lineno)d - %(message)s') + + 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) + logging.info("Trace level logging has been enabled") + + +class DebuggingLogHander(logging.Handler): + """ + A log handler used during testing to capture log records in memory so we + can validate what has been logged. + """ + def __init__(self): + logging.Handler.__init__(self) + self.records = [] + + def emit(self, record): + self.records.append(record) + + def reset(self): + self.records = [] + + def get_records(self): + return self.records diff --git a/lib/galaxy/webapps/galaxy/api/logging.py b/lib/galaxy/webapps/galaxy/api/logging.py new file mode 100644 index 000000000000..58f689813951 --- /dev/null +++ b/lib/galaxy/webapps/galaxy/api/logging.py @@ -0,0 +1,43 @@ +""" +API to allow admin users to view and set logging levels for Galaxy loggers. +""" + +import logging +import threading + +from galaxy.managers.context import ProvidesUserContext +from galaxy.util.logging import get_log_levels +from . import DependsOnTrans, Router + +log = logging.getLogger(__name__) +router = Router(tags=["logging"]) + +@router.cbv +class FastApiLoggingManager: + + @router.get( + "/api/logging", summary="Get logging levels for all configured loggers", require_admin=True + ) + def index(self, trans=DependsOnTrans): + log.info("Getting all logger leverls") + return get_log_levels(None) + + @router.get( + "/api/logging/{logger_name}", + summary="Get the logging level for one or more loggers", + response_description="The logging level for the logger(s)", + require_admin=True + ) + def get(self, logger_name, trans: ProvidesUserContext = DependsOnTrans): + log.info("Getting log level for %s", logger_name) + return get_log_levels(logger_name) + + @router.post( + "/api/logging/{logger_name}", summary="Set the level of a logger", require_admin=True + ) + def set(self, logger_name, level, trans: ProvidesUserContext = DependsOnTrans): + log.info("Setting log level for %s to %s", logger_name, level) + # We don't need the response, but we want to make sure the task is done before we return + trans.app.queue_worker.send_control_task("set_logging_levels", kwargs={"name":logger_name, "level":level}, get_response=True) + return get_log_levels(logger_name) + diff --git a/lib/galaxy_test/api/test_logging.py b/lib/galaxy_test/api/test_logging.py new file mode 100644 index 000000000000..1900853d4e07 --- /dev/null +++ b/lib/galaxy_test/api/test_logging.py @@ -0,0 +1,150 @@ +import logging + +from galaxy.util.logging import set_logging_levels_from_config, DebuggingLogHander + +set_logging_levels_from_config({ + 'galaxy.*': logging.ERROR, + 'galaxy.datatypes.display_applications.application': logging.CRITICAL, + 'galaxy.webapps.galaxy.api.logging.*': logging.TRACE, + 'galaxy_test.api.test_logging': logging.TRACE +}) + +from ._framework import ApiTestCase + + +SIMPLE_LOGGING_CONFIG = { + 'version': 1, + 'disable_existing_loggers': True, + 'handlers': { + 'console': { + 'class': 'logging.StreamHandler', + 'level': 'DEBUG', + 'formatter': 'simple', + 'stream': 'ext://sys.stdout' + } + }, + 'formatters': { + 'simple': { + 'format': '%(asctime)s - %(name)s - %(levelname)s - %(message)s' + } + }, + 'loggers': { + 'test': { + 'level': 'DEBUG', + 'handlers': ['console'] + } + } +} + +class TestLoggingApi(ApiTestCase): + + def test_logging_has_trace_level(self): + assert hasattr(logging, "TRACE") + assert hasattr(logging, "trace") + assert logging.TRACE == logging.DEBUG - 5 + + + def test_index(self): + logging.config.dictConfig(SIMPLE_LOGGING_CONFIG) + response = self._get("logging", admin=True) + response.raise_for_status() + logger_names = response.json() + # These are the only loggers that we can be sure are present. + assert "test" in logger_names + + + def test_get(self): + logging.config.dictConfig(SIMPLE_LOGGING_CONFIG) + response = self._get("logging/test", admin=True) + response.raise_for_status() + logger_levels = response.json() + assert len(logger_levels) == 1 + assert "test" in logger_levels + logger_level = logger_levels['test'] + assert logger_level["name"] == "test" + assert logger_level["level"] == "DEBUG" + assert logger_level["effective"] == "DEBUG" + + + def test_set(self): + logging.config.dictConfig(SIMPLE_LOGGING_CONFIG) + response = self._post("logging/test?level=CRITICAL", admin=True) #, data={"level": "CRITICAL"}) + print(response.text) + response.raise_for_status() + response = self._get("logging/test", admin=True) + response.raise_for_status() + logger_levels = response.json() + assert len(logger_levels) == 1 + assert "test" in logger_levels + logger_level = logger_levels["test"] + assert logger_level["name"] == "test" + assert logger_level["level"] == "CRITICAL" + assert logger_level["effective"] == "CRITICAL" + + # Verify that only CRITICAL messages are logged. + handler = DebuggingLogHander() + logger = logging.getLogger("test") + logger.addHandler(handler) + logger.info("INFO") + logger.warning("WARNING") + logger.error("ERROR") + logger.critical("CRITICAL") + records = handler.get_records() + assert len(records) == 1 + assert records[0].levelname == "CRITICAL" + assert records[0].message == "CRITICAL" + + def test_set_existing_logger(self): + logging.config.dictConfig(SIMPLE_LOGGING_CONFIG) + logger = logging.getLogger('test') + handler = DebuggingLogHander() + logger.addHandler(handler) + logger.trace("TRACE") + logger.debug("DEBUG") + logger.info("INFO") + records = handler.get_records() + assert len(records) == 2 + assert records[0].levelname == "DEBUG" + assert records[1].levelname == "INFO" + handler.reset() + + response = self._post("logging/test?level=INFO", admin=True) + response.raise_for_status() + response = self._get("logging/test", admin=True) + response.raise_for_status() + logger_levels = response.json() + assert len(logger_levels) == 1 + assert "test" in logger_levels + logger_level = logger_levels["test"] + assert logger_level["name"] == "test" + assert logger_level["level"] == "INFO" + assert logger_level["effective"] == "INFO" + logger.trace("TRACE") + logger.debug("DEBUG") + logger.info("INFO") + records = handler.get_records() + assert len(records) == 1 + assert records[0].levelname == "INFO" + handler.reset() + + response = self._post("logging/test?level=ERROR", admin=True) + response.raise_for_status() + response = self._get("logging/test", admin=True) + response.raise_for_status() + logger_levels = response.json() + assert len(logger_levels) == 1 + assert "test" in logger_levels + logger_level = logger_levels["test"] + assert logger_level["name"] == "test" + assert logger_level["level"] == "ERROR" + assert logger_level["effective"] == "ERROR" + logger.trace("TRACE") + logger.debug("DEBUG") + logger.info("INFO") + records = handler.get_records() + assert len(records) == 0 + handler.reset() + logger.error("ERROR") + records = handler.get_records() + assert len(records) == 1 + assert records[0].levelname == "ERROR" diff --git a/test/unit/util/test_logging.py b/test/unit/util/test_logging.py new file mode 100644 index 000000000000..70a86d56528a --- /dev/null +++ b/test/unit/util/test_logging.py @@ -0,0 +1,135 @@ +import logging.config +import types + + +from galaxy.util.logging import TRACE, get_logger_names, get_log_levels, set_log_levels, addTraceLoggingLevel +addTraceLoggingLevel() + + +SIMPLE_LOGGING_CONFIG = { + 'version': 1, + 'disable_existing_loggers': True, + 'handlers': { + 'console': { + 'class': 'logging.StreamHandler', + 'level': 'DEBUG', + 'formatter': 'simple', + 'stream': 'ext://sys.stdout', + }, + 'test': { + 'class': 'logging.StreamHandler', + 'level': 'DEBUG', + 'formatter': 'simple', + 'stream': 'ext://sys.stdout' + } + }, + 'formatters': { + 'simple': { + 'format': '%(name)s: %(message)s', + }, + }, + 'loggers': { + 'console': { + 'handlers': ['console'], + 'level': 'WARNING', + 'propagate': False, + }, + 'test': { + 'handlers': ['test'], + 'level': 'WARNING', + 'propagate': False, + } + }, +} + +def test_trace_level_exists(): + assert hasattr(logging, 'TRACE') + assert hasattr(logging, 'trace') + assert logging.TRACE == TRACE + assert type(getattr(logging, 'TRACE')) == int + assert isinstance(getattr(logging, 'trace'), types.FunctionType) + + +def test_logging_get_names(): + logging.config.dictConfig(SIMPLE_LOGGING_CONFIG) + + index = get_logger_names() + assert len(index) > 1 + # This is the only two loggers that we can be sure are present. + assert 'test' in index + + +def test_get_logging_levels(): + logging.config.dictConfig(SIMPLE_LOGGING_CONFIG) + levels = get_log_levels(None) + assert 'test' in levels + logger = levels['test'] + assert logger['level'] == 'WARNING' + assert logger['effective'] == 'WARNING' + + +def test_get_logging_level(): + logging.config.dictConfig(SIMPLE_LOGGING_CONFIG) + levels = get_log_levels('test') + assert len(levels) == 1 + assert 'test' in levels + logger = levels['test'] + assert logger['level'] == 'WARNING' + assert logger['effective'] == 'WARNING' + + +def test_set_level(): + logging.config.dictConfig(SIMPLE_LOGGING_CONFIG) + names = get_logger_names() + assert 'test' in names + levels = get_log_levels('test') + assert 'test' in levels + assert len(levels) == 1 + logger = levels['test'] + assert logger['level'] == 'WARNING' + set_log_levels('test', 'DEBUG') + assert get_log_levels('test')['test']['level'] == 'DEBUG' + + +def test_set_levels(): + import logging + logging.config.dictConfig(SIMPLE_LOGGING_CONFIG) + + a = logging.getLogger('a') + ab = logging.getLogger('a.b') + abc = logging.getLogger('a.b.c') + + assert a.getEffectiveLevel() == logging.DEBUG + assert ab.getEffectiveLevel() == logging.DEBUG + assert abc.getEffectiveLevel() == logging.DEBUG + + set_log_levels('a.*', 'INFO') + assert a.getEffectiveLevel() == logging.INFO + assert ab.getEffectiveLevel() == logging.INFO + assert abc.getEffectiveLevel() == logging.INFO + + set_log_levels('a.b.*', logging.WARNING) + assert a.getEffectiveLevel() == logging.INFO + assert ab.getEffectiveLevel() == logging.WARNING + assert abc.getEffectiveLevel() == logging.WARNING + + set_log_levels('a.b.c.*', logging.ERROR) + assert a.getEffectiveLevel() == logging.INFO + assert ab.getEffectiveLevel() == logging.WARNING + assert abc.getEffectiveLevel() == logging.ERROR + + set_log_levels('a.b.c', logging.CRITICAL) + assert a.getEffectiveLevel() == logging.INFO + assert ab.getEffectiveLevel() == logging.WARNING + assert abc.getEffectiveLevel() == logging.CRITICAL + + set_log_levels('a.b', logging.DEBUG) + assert a.getEffectiveLevel() == logging.INFO + assert ab.getEffectiveLevel() == logging.DEBUG + assert abc.getEffectiveLevel() == logging.CRITICAL + + set_log_levels('a', logging.TRACE) + assert a.getEffectiveLevel() == logging.TRACE + assert ab.getEffectiveLevel() == logging.DEBUG + assert abc.getEffectiveLevel() == logging.CRITICAL + From df9cdfb0983331235af9ba0fed2ced4533577899 Mon Sep 17 00:00:00 2001 From: Keith Suderman Date: Wed, 20 Nov 2024 15:56:41 -0500 Subject: [PATCH 2/6] Update API doc for the set method --- lib/galaxy/webapps/galaxy/api/logging.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/galaxy/webapps/galaxy/api/logging.py b/lib/galaxy/webapps/galaxy/api/logging.py index 58f689813951..686573aa8a3b 100644 --- a/lib/galaxy/webapps/galaxy/api/logging.py +++ b/lib/galaxy/webapps/galaxy/api/logging.py @@ -33,7 +33,7 @@ def get(self, logger_name, trans: ProvidesUserContext = DependsOnTrans): return get_log_levels(logger_name) @router.post( - "/api/logging/{logger_name}", summary="Set the level of a logger", require_admin=True + "/api/logging/{logger_name}", summary="Set the logging level for one or more loggers", require_admin=True ) def set(self, logger_name, level, trans: ProvidesUserContext = DependsOnTrans): log.info("Setting log level for %s to %s", logger_name, level) From 10f4f3cbf0a79c44fc071f03da942ae2a530282c Mon Sep 17 00:00:00 2001 From: Keith Suderman Date: Wed, 20 Nov 2024 16:02:04 -0500 Subject: [PATCH 3/6] Add Logging doc --- Logging.md | 91 ++++++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 91 insertions(+) create mode 100644 Logging.md diff --git a/Logging.md b/Logging.md new file mode 100644 index 000000000000..bba41a7aa636 --- /dev/null +++ b/Logging.md @@ -0,0 +1,91 @@ +This is a planning and discussion issue for enhancements I would like to make to Galaxy's logging system. + +# TL;DR + +I want to add a ton of `logger.trace()` calls to the Galaxy codebase, but before doing that we need to get some infrastructure in place. + +# What is proposed + +1. Enhance support for the `trace()` method that is already present in `galaxy.util.custom_logging` +1. Add a simplified logging configuration section to either `galaxy.yml` or a separate logging config file +1. Add API endpoints to query and set logging levels at runtime +1. Add an admin panel that gives administrators a GUI for setting log levels on a running instance. + +# What is not proposed + +1. Providing an API that allows arbitrary logger reconfiguration. We only need (want) to change the logging level at runtime. No other configuration changes will be allowed. +1. Changing the way loggers are currently configured. The logging configuration changes proposed here work transparently with the current logging configuration methods. +1. Catching all corner cases. Good enough is good enough. At least for now. +2. Doing everything now. This is a first pass and we can add more features and enhancements later. + +# Rationale + +Debugging Galaxy on Kubernetes clusters is difficult as there is no way to attach a debugger to a running instance and making code changes is time-consuming. Log messages are the best tool for obtaining runtime information and we don't do enough logging to trace program execution. + +# Proof of concept + +I have a proof of concept running that implements the first three items (everything but the admin panel), but before I start submitting PRs there are a number of design decisions to resolve. + +## The trace() method + +My proof of concept is based on the collective wisdom of [StackOverflow](https://stackoverflow.com/a/35804945/1691778). If we monkeypatch Python's `logging` library early enough in the code loading process then the `trace()` method is automagically available to all loggers. There are ~750 configured loggers in a running Galaxy instance. + +This works well in a running Galaxy instance, but presents problems for Galaxy packages meant to be used as libraries as we need to be sure that `galaxy.util.logging.addTraceLoggingLevel()` has been called before the first `logger.trace()` statement is encountered at runtime. + +We can: + +1. Require that package users call the `addTraceLoggingLevel()` method explicitly before doing anything else. +1. Find a way to ensure `addTraceLoggingLevel()` is called whenever a Galaxy package is imported. +1. Change almost every source file in the Galaxy code base to use `galaxy.util.custom_logging.get_logger()` or similar. + +The first option might be good enough until a better solution is decided on. +I lean towards -1 on the last option. One of the goals of this proposal is to make these enhancements as seamless and transparent as possible; changing almost every source file in the Galaxy codebase seems to be at odds with that goal. The `addTraceLoggingLevel` method is idempotent, so there should be a way to do #2. Perhaps simply calling `addTraceLoggingLevel()` in the [package.__init__.py](https://github.com/galaxyproject/galaxy/blob/dev/packages/package.__init__.py) file would be sufficient. + +## Logging configuration + +The proof of concept implementation adds a `logging_levels` section to the `galaxy.yml` file, although this could also be done in a separate configuration file. The purpose of the `logging_levels` section is not to replace any current methods for configuring logging, it just provides an additional and easier way to set the logging levels for groups of loggers in a single statement. + +``` +logging_levels: + galaxy.*: INFO + galaxy.jobs.runners.*: DEBUG + galaxy.jobs.runners.kubernetes: TRACE +``` +In this example the first statement sets the level for all loggers in the `galaxy` package and all sub-packages (`galaxy`, `galaxy.datatypes`, `galaxy.datatypes.converters`, `galaxy.datatypes.util`, and so on) to the INFO level. The second statement sets all loggers in the `galaxy.jobs.runners` packages, and the final statement sets the level for a single logger. + +## Changes at runtime + +Adding `trace()` level logging statements has the potential to blow up log files and Galaxy should not be configured to use `TRACE` as the default logging level. So we will need some way to enable `TRACE` level logging at runtime. Options include, but are not limited to: + +1. set up a file watcher on the config file and reconfigure loggers when changes are detected +2. provide an API that allows log levels to be changed. + +These are not mutually exclusive options, but in some situations, e.g. AnVIL, users may not have access to the configuration files. + +The proof of concept provides a simple API that allows the level to be changed at runtime. Adding a config watcher can be added at a later date if needed. + +Screenshot 2024-11-04 at 4 33 19 PM + +``` +curl http://localhost:8080/api/logging +curl http://localhost:8080/api/logging/galaxy.jobs.runners.* +curl -X POST http://localhost:8080/api/logging/galaxy.jobs.runners.*?level=DEBUG +curl -X POST http://localhost:8080/api/logging/galaxy.jobs.runners.kubernetes?level=TRACE +``` +The first `GET` method returns JSON containing information for all currently configured loggers. The second `GET` method returns information for a single logger or all loggers in a particular package. The `POST` method can be used to set the logging level for a single logger or all the loggers in a package. + +Are there other endpoints that should be included? Should we use different endpoints? + +# TODO + +## Authorization + +All API endpoints specify `require_admin=True` in the `@router` decorator. Is this sufficient? I was thinking of adding checks in relevant `galaxy.util.logging` methods, but is this necessary? + +## Admin GUI + +I have not started on an admin panel yet, but I envision it would be a new option in the *Server* section of the admin panel. The logging panel would contain a table and/or a tree view of all the loggers and their current levels and the ability to set the levels for loggers. I will definitely need some help and guidance with this task. + +## Naming + +I've used that I thought were reasonable names for the names of packages, API endpoints, function names, and configuration options, but I'm open to suggestions. This also applies to general code layout and structure. \ No newline at end of file From 3a6bbdbe0605e04699cc6df045353b3fb09b4373 Mon Sep 17 00:00:00 2001 From: Keith Suderman Date: Wed, 20 Nov 2024 18:15:51 -0500 Subject: [PATCH 4/6] Update the API images used in Logging.md --- Logging.md | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/Logging.md b/Logging.md index bba41a7aa636..bf89d85806bd 100644 --- a/Logging.md +++ b/Logging.md @@ -64,7 +64,7 @@ These are not mutually exclusive options, but in some situations, e.g. AnVIL, us The proof of concept provides a simple API that allows the level to be changed at runtime. Adding a config watcher can be added at a later date if needed. -Screenshot 2024-11-04 at 4 33 19 PM +Screenshot 2024-11-20 at 3 59 52 PM ``` curl http://localhost:8080/api/logging @@ -88,4 +88,4 @@ I have not started on an admin panel yet, but I envision it would be a new optio ## Naming -I've used that I thought were reasonable names for the names of packages, API endpoints, function names, and configuration options, but I'm open to suggestions. This also applies to general code layout and structure. \ No newline at end of file +I've used that I thought were reasonable names for the names of packages, API endpoints, function names, and configuration options, but I'm open to suggestions. This also applies to general code layout and structure. From 714552790f92d336fe9ead9aedb409f2c2c34d35 Mon Sep 17 00:00:00 2001 From: Keith Suderman Date: Mon, 25 Nov 2024 22:27:32 -0500 Subject: [PATCH 5/6] Update logging readme --- Logging.md | 36 +++++++++++++----------------------- 1 file changed, 13 insertions(+), 23 deletions(-) diff --git a/Logging.md b/Logging.md index bf89d85806bd..4cfad2063c46 100644 --- a/Logging.md +++ b/Logging.md @@ -15,47 +15,36 @@ I want to add a ton of `logger.trace()` calls to the Galaxy codebase, but before 1. Providing an API that allows arbitrary logger reconfiguration. We only need (want) to change the logging level at runtime. No other configuration changes will be allowed. 1. Changing the way loggers are currently configured. The logging configuration changes proposed here work transparently with the current logging configuration methods. -1. Catching all corner cases. Good enough is good enough. At least for now. 2. Doing everything now. This is a first pass and we can add more features and enhancements later. -# Rationale - -Debugging Galaxy on Kubernetes clusters is difficult as there is no way to attach a debugger to a running instance and making code changes is time-consuming. Log messages are the best tool for obtaining runtime information and we don't do enough logging to trace program execution. - # Proof of concept -I have a proof of concept running that implements the first three items (everything but the admin panel), but before I start submitting PRs there are a number of design decisions to resolve. - -## The trace() method +I have a proof of concept running that implements the first three items (everything but the admin panel). The code is available in the [logging-enhancements](https://github.com/ksuderman/galaxy/tree/logging-enhancements) branch of my Galaxy fork. -My proof of concept is based on the collective wisdom of [StackOverflow](https://stackoverflow.com/a/35804945/1691778). If we monkeypatch Python's `logging` library early enough in the code loading process then the `trace()` method is automagically available to all loggers. There are ~750 configured loggers in a running Galaxy instance. +However, before I start submitting PRs there are a number of design decisions to resolve. -This works well in a running Galaxy instance, but presents problems for Galaxy packages meant to be used as libraries as we need to be sure that `galaxy.util.logging.addTraceLoggingLevel()` has been called before the first `logger.trace()` statement is encountered at runtime. +## The trace() method -We can: +My proof of concept is based on the collective wisdom of [StackOverflow](https://stackoverflow.com/a/35804945/1691778). -1. Require that package users call the `addTraceLoggingLevel()` method explicitly before doing anything else. -1. Find a way to ensure `addTraceLoggingLevel()` is called whenever a Galaxy package is imported. -1. Change almost every source file in the Galaxy code base to use `galaxy.util.custom_logging.get_logger()` or similar. +If we monkeypatch Python's `logging` library early enough in the code loading process then the `trace()` method is automagically available to all loggers. There are ~750 configured loggers in a running Galaxy instance. -The first option might be good enough until a better solution is decided on. -I lean towards -1 on the last option. One of the goals of this proposal is to make these enhancements as seamless and transparent as possible; changing almost every source file in the Galaxy codebase seems to be at odds with that goal. The `addTraceLoggingLevel` method is idempotent, so there should be a way to do #2. Perhaps simply calling `addTraceLoggingLevel()` in the [package.__init__.py](https://github.com/galaxyproject/galaxy/blob/dev/packages/package.__init__.py) file would be sufficient. +This works well in a running Galaxy instance, but may present problems for Galaxy packages meant to be used as libraries. Calling `galaxy.util.logging.addTraceLoggingLevel()` in the [package.__init__.py](https://github.com/galaxyproject/galaxy/blob/dev/packages/package.__init__.py) may be sufficient. ## Logging configuration -The proof of concept implementation adds a `logging_levels` section to the `galaxy.yml` file, although this could also be done in a separate configuration file. The purpose of the `logging_levels` section is not to replace any current methods for configuring logging, it just provides an additional and easier way to set the logging levels for groups of loggers in a single statement. +The proof of concept implementation adds a `logging_levels` section to the `galaxy.yml` file. This could also be done in a separate configuration file. The purpose of the `logging_levels` section is to provide an easier way to set the logging levels for groups of loggers in a single statement. ``` logging_levels: - galaxy.*: INFO + galaxy.*: ERROR galaxy.jobs.runners.*: DEBUG galaxy.jobs.runners.kubernetes: TRACE ``` -In this example the first statement sets the level for all loggers in the `galaxy` package and all sub-packages (`galaxy`, `galaxy.datatypes`, `galaxy.datatypes.converters`, `galaxy.datatypes.util`, and so on) to the INFO level. The second statement sets all loggers in the `galaxy.jobs.runners` packages, and the final statement sets the level for a single logger. ## Changes at runtime -Adding `trace()` level logging statements has the potential to blow up log files and Galaxy should not be configured to use `TRACE` as the default logging level. So we will need some way to enable `TRACE` level logging at runtime. Options include, but are not limited to: +Adding `trace()` level logging statements has the potential to blow up log files and Galaxy should not be configured to use `TRACE` as the default logging level. We will need some way to enable `TRACE` level logging at runtime. Options include, but are not limited to: 1. set up a file watcher on the config file and reconfigure loggers when changes are detected 2. provide an API that allows log levels to be changed. @@ -72,9 +61,10 @@ curl http://localhost:8080/api/logging/galaxy.jobs.runners.* curl -X POST http://localhost:8080/api/logging/galaxy.jobs.runners.*?level=DEBUG curl -X POST http://localhost:8080/api/logging/galaxy.jobs.runners.kubernetes?level=TRACE ``` -The first `GET` method returns JSON containing information for all currently configured loggers. The second `GET` method returns information for a single logger or all loggers in a particular package. The `POST` method can be used to set the logging level for a single logger or all the loggers in a package. +For brevity I have omitted setting the API key. Only administrators can list or change the logging levels. -Are there other endpoints that should be included? Should we use different endpoints? + +The first `GET` method returns JSON containing information for all currently configured loggers. The second `GET` method returns information for a single logger or all loggers in a particular package. The `POST` method can be used to set the logging level for a single logger or all the loggers in a package. # TODO @@ -84,7 +74,7 @@ All API endpoints specify `require_admin=True` in the `@router` decorator. Is t ## Admin GUI -I have not started on an admin panel yet, but I envision it would be a new option in the *Server* section of the admin panel. The logging panel would contain a table and/or a tree view of all the loggers and their current levels and the ability to set the levels for loggers. I will definitely need some help and guidance with this task. +I have not started on an admin panel yet, but I envision it would be a new option in the *Server* section of the admin panel. The logging panel would contain a table and/or a tree view of all the loggers and their current levels and the ability to set the levels for loggers. I will need help and guidance with this task. ## Naming From 1e549e7db5374c3d5a56ef924e84082ef3a7e360 Mon Sep 17 00:00:00 2001 From: Keith Suderman Date: Mon, 10 Feb 2025 14:07:09 -0500 Subject: [PATCH 6/6] Update readme --- Logging.md | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/Logging.md b/Logging.md index 4cfad2063c46..ea611a8af4a5 100644 --- a/Logging.md +++ b/Logging.md @@ -2,7 +2,7 @@ This is a planning and discussion issue for enhancements I would like to make to # TL;DR -I want to add a ton of `logger.trace()` calls to the Galaxy codebase, but before doing that we need to get some infrastructure in place. +I want to add `logger.trace()` calls to the Galaxy codebase, but before doing that I would like to get some infrastructure in place. # What is proposed @@ -29,7 +29,7 @@ My proof of concept is based on the collective wisdom of [StackOverflow](https:/ If we monkeypatch Python's `logging` library early enough in the code loading process then the `trace()` method is automagically available to all loggers. There are ~750 configured loggers in a running Galaxy instance. -This works well in a running Galaxy instance, but may present problems for Galaxy packages meant to be used as libraries. Calling `galaxy.util.logging.addTraceLoggingLevel()` in the [package.__init__.py](https://github.com/galaxyproject/galaxy/blob/dev/packages/package.__init__.py) may be sufficient. +This works well in a running Galaxy instance, but may present problems for Galaxy packages meant to be used as libraries. Calling `galaxy.util.logging.addTraceLoggingLevel()` in the [package.__init__.py](https://github.com/galaxyproject/galaxy/blob/dev/packages/package.__init__.py) may be sufficient. The goal is to make it as easy as possible for developers to add `trace()` calls to their code and not require the use of a special logger class. ## Logging configuration @@ -44,7 +44,7 @@ logging_levels: ## Changes at runtime -Adding `trace()` level logging statements has the potential to blow up log files and Galaxy should not be configured to use `TRACE` as the default logging level. We will need some way to enable `TRACE` level logging at runtime. Options include, but are not limited to: +Adding `trace()` level logging statements has the potential to blow up log files and Galaxy should not be configured to use `TRACE` as the default logging level. Therefore we will need some way to enable `TRACE` level logging at runtime. Options include, but are not limited to: 1. set up a file watcher on the config file and reconfigure loggers when changes are detected 2. provide an API that allows log levels to be changed.