From 2fefa9fcd633bf6d713730c5f787402d7152ca53 Mon Sep 17 00:00:00 2001 From: Hemna Date: Fri, 1 Mar 2024 13:31:05 -0500 Subject: [PATCH 1/2] Replace slow rich logging with loguru This patch removes the rich logging with the modern loguru logging --- aprsd/cmds/webchat.py | 66 ++++------------- aprsd/conf/log.py | 18 +++-- aprsd/log/log.py | 109 ++++++++++++++++------------ aprsd/log/rich.py | 160 ------------------------------------------ requirements.in | 1 + requirements.txt | 1 + 6 files changed, 88 insertions(+), 267 deletions(-) delete mode 100644 aprsd/log/rich.py diff --git a/aprsd/cmds/webchat.py b/aprsd/cmds/webchat.py index b60556f..d6bd1f3 100644 --- a/aprsd/cmds/webchat.py +++ b/aprsd/cmds/webchat.py @@ -1,7 +1,6 @@ import datetime import json import logging -from logging.handlers import RotatingFileHandler import math import signal import sys @@ -12,7 +11,6 @@ from aprslib import util as aprslib_util import click import flask from flask import request -from flask.logging import default_handler from flask_httpauth import HTTPBasicAuth from flask_socketio import Namespace, SocketIO from geopy.distance import geodesic @@ -21,11 +19,13 @@ from werkzeug.security import check_password_hash, generate_password_hash import wrapt import aprsd -from aprsd import cli_helper, client, conf, packets, stats, threads, utils, plugin_utils -from aprsd.log import rich as aprsd_logging +from aprsd import ( + cli_helper, client, packets, plugin_utils, stats, threads, utils, +) +from aprsd.log import log from aprsd.main import cli -from aprsd.threads import rx, tx from aprsd.threads import aprsd as aprsd_threads +from aprsd.threads import rx, tx from aprsd.utils import trace @@ -181,7 +181,7 @@ def _build_location_from_repeat(message): a = message.split(":") LOG.warning(a) if len(a) == 2: - callsign = a[0].replace('^ld^', '') + callsign = a[0].replace("^ld^", "") b = a[1].split(",") LOG.warning(b) if len(b) == 6: @@ -282,13 +282,13 @@ def populate_callsign_location(callsign, data=None): except Exception: alt = 0 location_data = { - 'callsign': callsign, - 'lat': lat, - 'lon': lon, - 'altitude': alt, - 'lasttime': int(aprs_data["entries"][0]["lasttime"]), - 'course': float(aprs_data["entries"][0].get("course", 0)), - 'speed': float(aprs_data["entries"][0].get("speed", 0)), + "callsign": callsign, + "lat": lat, + "lon": lon, + "altitude": alt, + "lasttime": int(aprs_data["entries"][0]["lasttime"]), + "course": float(aprs_data["entries"][0].get("course", 0)), + "speed": float(aprs_data["entries"][0].get("speed", 0)), } location_data = _calculate_location_data(location_data) callsign_locations[callsign] = location_data @@ -339,7 +339,7 @@ class WebChatProcessPacketThread(rx.APRSDProcessPacketThread): # ok lets see if we have the location for the # person we just sent a message to. from_call = packet.get("from_call").upper() - if from_call == 'REPEAT': + if from_call == "REPEAT": # We got a message from REPEAT. Is this a location message? message = packet.get("message_text") if message.startswith("^ld^"): @@ -568,52 +568,16 @@ class SendMessageNamespace(Namespace): populate_callsign_location(data["callsign"]) -def setup_logging(flask_app, loglevel, quiet): - flask_log = logging.getLogger("werkzeug") - flask_app.logger.removeHandler(default_handler) - flask_log.removeHandler(default_handler) - - log_level = conf.log.LOG_LEVELS[loglevel] - flask_log.setLevel(log_level) - date_format = CONF.logging.date_format - - if CONF.logging.rich_logging and not quiet: - log_format = "%(message)s" - log_formatter = logging.Formatter(fmt=log_format, datefmt=date_format) - rh = aprsd_logging.APRSDRichHandler( - show_thread=True, thread_width=15, - rich_tracebacks=True, omit_repeated_times=False, - ) - rh.setFormatter(log_formatter) - flask_log.addHandler(rh) - - log_file = CONF.logging.logfile - - if log_file: - log_format = CONF.logging.logformat - log_formatter = logging.Formatter(fmt=log_format, datefmt=date_format) - fh = RotatingFileHandler( - log_file, maxBytes=(10248576 * 5), - backupCount=4, - ) - fh.setFormatter(log_formatter) - flask_log.addHandler(fh) - - @trace.trace def init_flask(loglevel, quiet): global socketio, flask_app - setup_logging(flask_app, loglevel, quiet) + log.setup_logging(loglevel, quiet) socketio = SocketIO( flask_app, logger=False, engineio_logger=False, async_mode="threading", ) - # async_mode="gevent", - # async_mode="eventlet", - # import eventlet - # eventlet.monkey_patch() socketio.on_namespace( SendMessageNamespace( diff --git a/aprsd/conf/log.py b/aprsd/conf/log.py index 5a4af95..cbe9247 100644 --- a/aprsd/conf/log.py +++ b/aprsd/conf/log.py @@ -20,21 +20,19 @@ DEFAULT_LOG_FORMAT = ( " %(message)s - [%(pathname)s:%(lineno)d]" ) +DEFAULT_LOG_FORMAT = ( + "{time:YYYY-MM-DD HH:mm:ss.SSS} | " + "{level: <8} | " + "{thread.name: <18} | " + "{message} | " + "{name}:{function:}:{line:}" +) + logging_group = cfg.OptGroup( name="logging", title="Logging options", ) logging_opts = [ - cfg.StrOpt( - "date_format", - default=DEFAULT_DATE_FORMAT, - help="Date format for log entries", - ), - cfg.BoolOpt( - "rich_logging", - default=True, - help="Enable Rich log", - ), cfg.StrOpt( "logfile", default=None, diff --git a/aprsd/log/log.py b/aprsd/log/log.py index 2a53071..f21a148 100644 --- a/aprsd/log/log.py +++ b/aprsd/log/log.py @@ -1,13 +1,13 @@ import logging from logging import NullHandler -from logging.handlers import RotatingFileHandler +from logging.handlers import QueueHandler import queue import sys +from loguru import logger from oslo_config import cfg from aprsd import conf -from aprsd.log import rich as aprsd_logging CONF = cfg.CONF @@ -15,61 +15,78 @@ LOG = logging.getLogger("APRSD") logging_queue = queue.Queue() +class InterceptHandler(logging.Handler): + def emit(self, record): + # get corresponding Loguru level if it exists + try: + level = logger.level(record.levelname).name + except ValueError: + level = record.levelno + + # find caller from where originated the logged message + frame, depth = sys._getframe(6), 6 + while frame and frame.f_code.co_filename == logging.__file__: + frame = frame.f_back + depth += 1 + + logger.opt(depth=depth, exception=record.exc_info).log(level, record.getMessage()) + + # Setup the log faciility # to disable log to stdout, but still log to file # use the --quiet option on the cmdln -def setup_logging(loglevel, quiet): - log_level = conf.log.LOG_LEVELS[loglevel] - LOG.setLevel(log_level) - date_format = CONF.logging.date_format - rh = None - fh = None +def setup_logging(loglevel=None, quiet=False): + if not loglevel: + log_level = CONF.logging.log_level + else: + log_level = conf.log.LOG_LEVELS[loglevel] - rich_logging = False - if CONF.logging.get("rich_logging", False) and not quiet: - log_format = "%(message)s" - log_formatter = logging.Formatter(fmt=log_format, datefmt=date_format) - rh = aprsd_logging.APRSDRichHandler( - show_thread=True, thread_width=20, - rich_tracebacks=True, omit_repeated_times=False, + # intercept everything at the root logger + logging.root.handlers = [InterceptHandler()] + logging.root.setLevel(log_level) + + # remove every other logger's handlers + # and propagate to root logger + for name in logging.root.manager.loggerDict.keys(): + logging.getLogger(name).handlers = [] + if name in ["imapclient.imaplib", "imaplib", "imapclient", "imapclient.util"]: + logging.getLogger(name).propagate = False + else: + logging.getLogger(name).propagate = True + + handlers = [ + { + "sink": sys.stdout, "serialize": False, + "format": CONF.logging.logformat, + }, + ] + if CONF.logging.logfile: + handlers.append( + { + "sink": CONF.logging.logfile, "serialize": False, + "format": CONF.logging.logformat, + }, ) - rh.setFormatter(log_formatter) - LOG.addHandler(rh) - rich_logging = True - log_file = CONF.logging.logfile - log_format = CONF.logging.logformat - log_formatter = logging.Formatter(fmt=log_format, datefmt=date_format) - - if log_file: - fh = RotatingFileHandler(log_file, maxBytes=(10248576 * 5), backupCount=4) - fh.setFormatter(log_formatter) - LOG.addHandler(fh) - - imap_logger = None if CONF.email_plugin.enabled and CONF.email_plugin.debug: - imap_logger = logging.getLogger("imapclient.imaplib") - imap_logger.setLevel(log_level) - if rh: - imap_logger.addHandler(rh) - if fh: - imap_logger.addHandler(fh) + imaps = [ + "imapclient.imaplib", "imaplib", "imapclient", + "imapclient.util", + ] + for name in imaps: + logging.getLogger(name).propagate = True if CONF.admin.web_enabled: - qh = logging.handlers.QueueHandler(logging_queue) - q_log_formatter = logging.Formatter( - fmt=CONF.logging.logformat, - datefmt=CONF.logging.date_format, + qh = QueueHandler(logging_queue) + handlers.append( + { + "sink": qh, "serialize": False, + "format": CONF.logging.logformat, + }, ) - qh.setFormatter(q_log_formatter) - LOG.addHandler(qh) - if not quiet and not rich_logging: - sh = logging.StreamHandler(sys.stdout) - sh.setFormatter(log_formatter) - LOG.addHandler(sh) - if imap_logger: - imap_logger.addHandler(sh) + # configure loguru + logger.configure(handlers=handlers) def setup_logging_no_config(loglevel, quiet): diff --git a/aprsd/log/rich.py b/aprsd/log/rich.py deleted file mode 100644 index 1d70160..0000000 --- a/aprsd/log/rich.py +++ /dev/null @@ -1,160 +0,0 @@ -from datetime import datetime -from logging import LogRecord -from pathlib import Path -from typing import TYPE_CHECKING, Callable, Iterable, List, Optional, Union - -from rich._log_render import LogRender -from rich.logging import RichHandler -from rich.text import Text, TextType -from rich.traceback import Traceback - - -if TYPE_CHECKING: - from rich.console import Console, ConsoleRenderable, RenderableType - from rich.table import Table - -from aprsd import utils - - -FormatTimeCallable = Callable[[datetime], Text] - - -class APRSDRichLogRender(LogRender): - - def __init__( - self, *args, - show_thread: bool = False, - thread_width: Optional[int] = 10, - **kwargs, - ): - super().__init__(*args, **kwargs) - self.show_thread = show_thread - self.thread_width = thread_width - - def __call__( - self, - console: "Console", - renderables: Iterable["ConsoleRenderable"], - log_time: Optional[datetime] = None, - time_format: Optional[Union[str, FormatTimeCallable]] = None, - level: TextType = "", - path: Optional[str] = None, - line_no: Optional[int] = None, - link_path: Optional[str] = None, - thread_name: Optional[str] = None, - ) -> "Table": - from rich.containers import Renderables - from rich.table import Table - - output = Table.grid(padding=(0, 1)) - output.expand = True - if self.show_time: - output.add_column(style="log.time") - if self.show_thread: - rgb = str(utils.rgb_from_name(thread_name)).replace(" ", "") - output.add_column(style=f"rgb{rgb}", width=self.thread_width) - if self.show_level: - output.add_column(style="log.level", width=self.level_width) - output.add_column(ratio=1, style="log.message", overflow="fold") - if self.show_path and path: - output.add_column(style="log.path") - row: List["RenderableType"] = [] - if self.show_time: - log_time = log_time or console.get_datetime() - time_format = time_format or self.time_format - if callable(time_format): - log_time_display = time_format(log_time) - else: - log_time_display = Text(log_time.strftime(time_format)) - if log_time_display == self._last_time and self.omit_repeated_times: - row.append(Text(" " * len(log_time_display))) - else: - row.append(log_time_display) - self._last_time = log_time_display - if self.show_thread: - row.append(thread_name) - if self.show_level: - row.append(level) - - row.append(Renderables(renderables)) - if self.show_path and path: - path_text = Text() - path_text.append( - path, style=f"link file://{link_path}" if link_path else "", - ) - if line_no: - path_text.append(":") - path_text.append( - f"{line_no}", - style=f"link file://{link_path}#{line_no}" if link_path else "", - ) - row.append(path_text) - - output.add_row(*row) - return output - - -class APRSDRichHandler(RichHandler): - """APRSD's extension of rich's RichHandler to show threads. - - show_thread (bool, optional): Show the name of the thread in log entry. Defaults to False. - thread_width (int, optional): The number of characters to show for thread name. Defaults to 10. - """ - - def __init__( - self, *args, - show_thread: bool = True, - thread_width: Optional[int] = 10, - **kwargs, - ): - super().__init__(*args, **kwargs) - self.show_thread = show_thread - self.thread_width = thread_width - kwargs["show_thread"] = show_thread - kwargs["thread_width"] = thread_width - self._log_render = APRSDRichLogRender( - show_time=True, - show_level=True, - show_path=True, - omit_repeated_times=False, - level_width=None, - show_thread=show_thread, - thread_width=thread_width, - ) - - def render( - self, *, record: LogRecord, - traceback: Optional[Traceback], - message_renderable: "ConsoleRenderable", - ) -> "ConsoleRenderable": - """Render log for display. - - Args: - record (LogRecord): log Record. - traceback (Optional[Traceback]): Traceback instance or None for no Traceback. - message_renderable (ConsoleRenderable): Renderable (typically Text) containing log message contents. - - Returns: - ConsoleRenderable: Renderable to display log. - """ - path = Path(record.pathname).name - level = self.get_level_text(record) - time_format = None if self.formatter is None else self.formatter.datefmt - log_time = datetime.fromtimestamp(record.created) - thread_name = record.threadName - - log_renderable = self._log_render( - self.console, - [message_renderable] if not traceback else [ - message_renderable, - traceback, - ], - log_time=log_time, - time_format=time_format, - level=level, - path=path, - line_no=record.lineno, - link_path=record.pathname if self.enable_link_path else None, - thread_name=thread_name, - ) - return log_renderable diff --git a/requirements.in b/requirements.in index 8a47982..e5599fb 100644 --- a/requirements.in +++ b/requirements.in @@ -37,3 +37,4 @@ shellingham geopy rush dataclasses-json +loguru diff --git a/requirements.txt b/requirements.txt index 86a7bdf..6122800 100644 --- a/requirements.txt +++ b/requirements.txt @@ -38,6 +38,7 @@ importlib-metadata==7.0.1 # via ax253, kiss3 itsdangerous==2.1.2 # via flask jinja2==3.1.3 # via click-completion, flask kiss3==8.0.0 # via -r requirements.in +loguru==0.7.2 # via -r requirements.in markupsafe==2.1.5 # via jinja2, werkzeug marshmallow==3.21.1 # via dataclasses-json mypy-extensions==1.0.0 # via typing-inspect From 2cb9c2a31cf88904381f5e2aa456be77941d9ecb Mon Sep 17 00:00:00 2001 From: Hemna Date: Wed, 6 Mar 2024 13:39:51 -0500 Subject: [PATCH 2/2] Put threads first after date/time --- aprsd/conf/log.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/aprsd/conf/log.py b/aprsd/conf/log.py index cbe9247..5d4fa9d 100644 --- a/aprsd/conf/log.py +++ b/aprsd/conf/log.py @@ -22,8 +22,8 @@ DEFAULT_LOG_FORMAT = ( DEFAULT_LOG_FORMAT = ( "{time:YYYY-MM-DD HH:mm:ss.SSS} | " - "{level: <8} | " "{thread.name: <18} | " + "{level: <8} | " "{message} | " "{name}:{function:}:{line:}" )