From de029aa103d195a52c630f6d7293a6b8392df2f2 Mon Sep 17 00:00:00 2001 From: karlicoss Date: Sat, 28 Oct 2023 02:45:38 +0100 Subject: [PATCH] core: switch to updated logging helper which is used in other projects --- pyproject.toml | 3 + src/orger/common.py | 7 +- src/orger/klogging.py | 66 ---------- src/orger/logging_helper.py | 241 ++++++++++++++++++++++++++++++++++++ src/orger/org_view.py | 8 +- tox.ini | 4 +- 6 files changed, 253 insertions(+), 76 deletions(-) delete mode 100644 src/orger/klogging.py create mode 100644 src/orger/logging_helper.py diff --git a/pyproject.toml b/pyproject.toml index e76c02a..c38ea50 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -23,6 +23,9 @@ Homepage = "https://github.com/karlicoss/orger" ## [project.optional-dependencies] +optional = [ + "colorlog", +] testing = [ "pytest", "ruff", diff --git a/src/orger/common.py b/src/orger/common.py index e767047..150b988 100644 --- a/src/orger/common.py +++ b/src/orger/common.py @@ -53,10 +53,9 @@ def todo(dt: datetime, **kwargs): ) -# todo use klogging2? -from .klogging import LazyLogger, setup_logger - - def orger_user_dir() -> Path: import appdirs return Path(appdirs.user_config_dir('orger')) + + +from .logging_helper import LazyLogger, setup_logger # legacy imports for bwd compatibility diff --git a/src/orger/klogging.py b/src/orger/klogging.py deleted file mode 100644 index 919298a..0000000 --- a/src/orger/klogging.py +++ /dev/null @@ -1,66 +0,0 @@ -#!/usr/bin/env python3 -import logging -from typing import Union, Optional, cast - -Level = int -LevelIsh = Optional[Union[Level, str]] - - -def mklevel(level: LevelIsh) -> Level: - if level is None: - return logging.NOTSET - if isinstance(level, int): - return level - return getattr(logging, level.upper()) - - -_FMT = '{start}[%(levelname)-7s %(asctime)s %(name)s %(filename)s:%(lineno)d]{end} %(message)s' -_FMT_COLOR = _FMT.format(start='%(color)s', end='%(end_color)s') -_FMT_NOCOLOR = _FMT.format(start='', end='') - - -def setup_logger(logger: logging.Logger, level: Level) -> None: - try: - import logzero # type: ignore - except ModuleNotFoundError: - import warnings - warnings.warn("You might want to install 'logzero' for nice colored logs!") - logger.setLevel(level) - h = logging.StreamHandler() - h.setLevel(level) - h.setFormatter(logging.Formatter(fmt=_FMT_NOCOLOR)) - logger.addHandler(h) - else: - formatter = logzero.LogFormatter( - fmt=_FMT_COLOR, - datefmt=None, # pass None to prevent logzero from messing with date format - ) - logzero.setup_logger(logger.name, level=level, formatter=formatter) - - -class LazyLogger(logging.Logger): - def __new__(cls, name: str, level: LevelIsh = 'DEBUG') -> 'LazyLogger': - logger = logging.getLogger(name) - lvl = mklevel(level) - - # this is called prior to all _log calls so makes sense to do it here? - def isEnabledFor_lazyinit(*args, logger=logger, orig=logger.isEnabledFor, **kwargs): - att = 'lazylogger_init_done' - if not getattr(logger, att, False): # init once, if necessary - setup_logger(logger, level=lvl) - setattr(logger, att, True) - return orig(*args, **kwargs) - - logger.isEnabledFor = isEnabledFor_lazyinit # type: ignore[method-assign] - return cast(LazyLogger, logger) - - -def test() -> None: - ll = LazyLogger('test') - ll.debug('THIS IS DEBUG') - ll.warning('THIS IS WARNING') - ll.exception(RuntimeError("oops")) - - -if __name__ == '__main__': - test() diff --git a/src/orger/logging_helper.py b/src/orger/logging_helper.py new file mode 100644 index 0000000..154f977 --- /dev/null +++ b/src/orger/logging_helper.py @@ -0,0 +1,241 @@ +from __future__ import annotations + +from functools import lru_cache +import logging +import os +import sys +from typing import Union +import warnings + + +def test() -> None: + from typing import Callable + + M: Callable[[str], None] = lambda s: print(s, file=sys.stderr) + + ## prepare exception for later + try: + None.whatever # type: ignore[attr-defined] + except Exception as e: + ex = e + ## + + M(" Logging module's defaults are not great:") + l = logging.getLogger('default_logger') + l.error("For example, this should be logged as error. But it's not even formatted properly, doesn't have logger name or level") + + M("\n The reason is that you need to remember to call basicConfig() first. Let's do it now:") + logging.basicConfig() + l.error("OK, this is better. But the default format kinda sucks, I prefer having timestamps and the file/line number") + + M("\n Also exception logging is kinda lame, doesn't print traceback by default unless you remember to pass exc_info:") + l.exception(ex) # type: ignore[possibly-undefined] + + M("\n\n With make_logger you get a reasonable logging format, colours (via colorlog library) and other neat things:") + + ll = make_logger('test') # No need for basicConfig! + ll.info("default level is INFO") + ll.debug("... so this shouldn't be displayed") + ll.warning("warnings are easy to spot!") + + M("\n Exceptions print traceback by default now:") + ll.exception(ex) + + M("\n You can (and should) use it via regular logging.getLogger after that, e.g. let's set logging level to DEBUG now") + logging.getLogger('test').setLevel(logging.DEBUG) + ll.debug("... now debug messages are also displayed") + + +DEFAULT_LEVEL = 'INFO' +FORMAT = '{start}[%(levelname)-7s %(asctime)s %(name)s %(filename)s:%(lineno)-4d]{end} %(message)s' +FORMAT_NOCOLOR = FORMAT.format(start='', end='') + + +Level = int +LevelIsh = Union[Level, str, None] + + +def mklevel(level: LevelIsh) -> Level: + if level is None: + return logging.NOTSET + if isinstance(level, int): + return level + return getattr(logging, level.upper()) + + +def get_collapse_level() -> Level | None: + # TODO not sure if should be specific to logger name? + cl = os.environ.get('LOGGING_COLLAPSE', None) + if cl is not None: + return mklevel(cl) + # legacy name, maybe deprecate? + cl = os.environ.get('COLLAPSE_DEBUG_LOGS', None) + if cl is not None: + return logging.DEBUG + return None + + +def get_env_level(name: str) -> Level | None: + PREFIX = 'LOGGING_LEVEL_' # e.g. LOGGING_LEVEL_my_hypothesis=debug + # shell doesn't allow using dots in var names without escaping, so also support underscore syntax + lvl = os.environ.get(PREFIX + name, None) or os.environ.get(PREFIX + name.replace('.', '_'), None) + if lvl is not None: + return mklevel(lvl) + return None + + +def setup_logger(logger: str | logging.Logger, *, level: LevelIsh = None) -> None: + """ + Wrapper to simplify logging setup. + """ + if isinstance(logger, str): + logger = logging.getLogger(logger) + + if level is None: + level = DEFAULT_LEVEL + + # env level always takes precedence + env_level = get_env_level(logger.name) + if env_level is not None: + lvl = env_level + else: + lvl = mklevel(level) + + if logger.level == logging.NOTSET: + # if it's already set, the user requested a different logging level, let's respect that + logger.setLevel(lvl) + + _setup_handlers_and_formatters(name=logger.name) + + +# cached since this should only be done once per logger instance +@lru_cache(None) +def _setup_handlers_and_formatters(name: str) -> None: + logger = logging.getLogger(name) + + logger.addFilter(AddExceptionTraceback()) + + collapse_level = get_collapse_level() + if collapse_level is None or not sys.stderr.isatty(): + handler = logging.StreamHandler() + else: + handler = CollapseLogsHandler(maxlevel=collapse_level) + + # default level for handler is NOTSET, which will make it process all messages + # we rely on the logger to actually accept/reject log msgs + logger.addHandler(handler) + + # this attribute is set to True by default, which causes log entries to be passed to root logger (e.g. if you call basicConfig beforehand) + # even if log entry is handled by this logger ... not sure what's the point of this behaviour?? + logger.propagate = False + + try: + # try colorlog first, so user gets nice colored logs + import colorlog + except ModuleNotFoundError: + warnings.warn("You might want to 'pip install colorlog' for nice colored logs") + formatter = logging.Formatter(FORMAT_NOCOLOR) + else: + # log_color/reset are specific to colorlog + FORMAT_COLOR = FORMAT.format(start='%(log_color)s', end='%(reset)s') + # colorlog should detect tty in principle, but doesn't handle everything for some reason + # see https://github.com/borntyping/python-colorlog/issues/71 + if handler.stream.isatty(): + formatter = colorlog.ColoredFormatter(FORMAT_COLOR) + else: + formatter = logging.Formatter(FORMAT_NOCOLOR) + + handler.setFormatter(formatter) + + +# by default, logging.exception isn't logging traceback unless called inside of the exception handler +# which is a bit annoying since we have to pass exc_info explicitly +# also see https://stackoverflow.com/questions/75121925/why-doesnt-python-logging-exception-method-log-traceback-by-default +# todo also amend by post about defensive error handling? +class AddExceptionTraceback(logging.Filter): + def filter(self, record: logging.LogRecord) -> bool: + if record.levelname == 'ERROR': + exc = record.msg + if isinstance(exc, BaseException): + if record.exc_info is None or record.exc_info == (None, None, None): + exc_info = (type(exc), exc, exc.__traceback__) + record.exc_info = exc_info + return True + + +# todo also save full log in a file? +class CollapseLogsHandler(logging.StreamHandler): + ''' + Collapses subsequent debug log lines and redraws on the same line. + Hopefully this gives both a sense of progress and doesn't clutter the terminal as much? + ''' + + last: bool = False + + maxlevel: Level = logging.DEBUG # everything with less or equal level will be collapsed + + def __init__(self, *args, maxlevel: Level, **kwargs) -> None: + super().__init__(*args, **kwargs) + self.maxlevel = maxlevel + + def emit(self, record: logging.LogRecord) -> None: + try: + msg = self.format(record) + cur = record.levelno <= self.maxlevel and '\n' not in msg + if cur: + if self.last: + self.stream.write('\033[K' + '\r') # clear line + return carriage + else: + if self.last: + self.stream.write('\n') # clean up after the last line + self.last = cur + columns, _ = os.get_terminal_size(0) + # ugh. the columns thing is meh. dunno I guess ultimately need curses for that + # TODO also would be cool to have a terminal post-processor? kinda like tail but aware of logging keywords (INFO/DEBUG/etc) + self.stream.write(msg + ' ' * max(0, columns - len(msg)) + ('' if cur else '\n')) + self.flush() + except: + self.handleError(record) + + +def make_logger(name: str, *, level: LevelIsh = None) -> logging.Logger: + logger = logging.getLogger(name) + setup_logger(logger, level=level) + return logger + + +# ughh. hacky way to have a single enlighten instance per interpreter, so it can be shared between modules +# not sure about this. I guess this should definitely be behind some flag +# OK, when stdout is not a tty, enlighten doesn't log anything, good +def get_enlighten(): + # TODO could add env variable to disable enlighten for a module? + from unittest.mock import Mock # Mock to return stub so cients don't have to think about it + + # for now hidden behind the flag since it's a little experimental + if os.environ.get('ENLIGHTEN_ENABLE', None) is None: + return Mock() + + try: + import enlighten # type: ignore[import-not-found] + except ModuleNotFoundError: + warnings.warn("You might want to 'pip install enlighten' for a nice progress bar") + + return Mock() + + # dirty, but otherwise a bit unclear how to share enlighten manager between packages that call each other + instance = getattr(enlighten, 'INSTANCE', None) + if instance is not None: + return instance + instance = enlighten.get_manager() + setattr(enlighten, 'INSTANCE', instance) + return instance + + +if __name__ == '__main__': + test() + + +## legacy/deprecated methods for backwards compatilibity +LazyLogger = make_logger +logger = make_logger +## diff --git a/src/orger/org_view.py b/src/orger/org_view.py index c762b40..3b4ea98 100644 --- a/src/orger/org_view.py +++ b/src/orger/org_view.py @@ -2,7 +2,6 @@ import argparse from argparse import ArgumentParser, Namespace from collections import Counter -import logging import inspect import json from pathlib import Path @@ -13,7 +12,9 @@ from .inorganic import OrgNode, TimestampStyle from .state import JsonState from .atomic_append import atomic_append_check, assert_not_edited -from .common import setup_logger, orger_user_dir +from .common import orger_user_dir +from .logging_helper import make_logger + # TODO tests for determinism? not sure where should they be... # think of some generic thing to test that? @@ -39,7 +40,7 @@ def __init__( ) -> None: self.cmdline_args: Namespace = cmdline_args if cmdline_args is not None else Namespace() tag = self.name() if self.logger_tag is None else self.logger_tag - self.logger = logging.getLogger(tag) + self.logger = make_logger(tag, level='debug') tool = Path(inspect.getfile(self.__class__)).absolute() self.file_header = file_header if file_header is not None else self.DEFAULT_HEADER.format(tool=tool) @@ -61,7 +62,6 @@ def main_common(self) -> None: from .common import settings # hacky, but does the trick for now... settings.DEFAULT_TIMESTAMP_STYLE = _style_map[timestamp_style] - setup_logger(self.logger, level=logging.DEBUG) pandoc = self.args.pandoc settings.USE_PANDOC = pandoc diff --git a/tox.ini b/tox.ini index 209ee3d..20e80ac 100644 --- a/tox.ini +++ b/tox.ini @@ -39,7 +39,7 @@ commands = [testenv:mypy-core] commands = - {envpython} -m pip install --use-pep517 -e .[testing] + {envpython} -m pip install --use-pep517 -e .[testing,optional] {envpython} -m mypy --install-types --non-interactive \ -p {[testenv]package_name} \ --exclude 'orger.modules' \ @@ -52,7 +52,7 @@ commands = [testenv:mypy-misc] commands = - {envpython} -m pip install --use-pep517 -e .[testing] + {envpython} -m pip install --use-pep517 -e .[testing,optional] {envpython} -m pip install HPI {envpython} -m my.core module install my.pocket {envpython} -m my.core module install my.reddit