Merge pull request #147 from craigerl/loguru

Replace slow rich logging with loguru

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 import (
-from aprsd.log import rich as aprsd_logging
+    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,
+                "callsign": callsign,
-                'lat': lat,
+                "lat": lat,
-                'lon': lon,
+                "lon": lon,
-                'altitude': alt,
+                "altitude": alt,
-                'lasttime': int(aprs_data["entries"][0]["lasttime"]),
+                "lasttime": int(aprs_data["entries"][0]["lasttime"]),
-                'course': float(aprs_data["entries"][0].get("course", 0)),
+                "course": float(aprs_data["entries"][0].get("course", 0)),
-                'speed': float(aprs_data["entries"][0].get("speed", 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(

aprsd/conf/log.py

@@ -20,21 +20,19 @@ DEFAULT_LOG_FORMAT = (
     " %(message)s - [%(pathname)s:%(lineno)d]"
 )
 
+DEFAULT_LOG_FORMAT = (
+    "<green>{time:YYYY-MM-DD HH:mm:ss.SSS}</green> | "
+    "<yellow>{thread.name: <18}</yellow> | "
+    "<level>{level: <8}</level> | "
+    "<level>{message}</level> | "
+    "<cyan>{name}</cyan>:<cyan>{function:}</cyan>:<magenta>{line:}</magenta>"
+)
+
 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,

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):
+def setup_logging(loglevel=None, quiet=False):
-    log_level = conf.log.LOG_LEVELS[loglevel]
+    if not loglevel:
-    LOG.setLevel(log_level)
+        log_level = CONF.logging.log_level
-    date_format = CONF.logging.date_format
+    else:
-    rh = None
+        log_level = conf.log.LOG_LEVELS[loglevel]
-    fh = None
 
-    rich_logging = False
+    # intercept everything at the root logger
-    if CONF.logging.get("rich_logging", False) and not quiet:
+    logging.root.handlers = [InterceptHandler()]
-        log_format = "%(message)s"
+    logging.root.setLevel(log_level)
-        log_formatter = logging.Formatter(fmt=log_format, datefmt=date_format)
+
-        rh = aprsd_logging.APRSDRichHandler(
+    # remove every other logger's handlers
-            show_thread=True, thread_width=20,
+    # and propagate to root logger
-            rich_tracebacks=True, omit_repeated_times=False,
+    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")
+        imaps = [
-        imap_logger.setLevel(log_level)
+            "imapclient.imaplib", "imaplib", "imapclient",
-        if rh:
+            "imapclient.util",
-            imap_logger.addHandler(rh)
+        ]
-        if fh:
+        for name in imaps:
-            imap_logger.addHandler(fh)
+            logging.getLogger(name).propagate = True
 
     if CONF.admin.web_enabled:
-        qh = logging.handlers.QueueHandler(logging_queue)
+        qh = QueueHandler(logging_queue)
-        q_log_formatter = logging.Formatter(
+        handlers.append(
-            fmt=CONF.logging.logformat,
+            {
-            datefmt=CONF.logging.date_format,
+                "sink": qh, "serialize": False,
+                "format": CONF.logging.logformat,
+            },
         )
-        qh.setFormatter(q_log_formatter)
-        LOG.addHandler(qh)
 
-    if not quiet and not rich_logging:
+    # configure loguru
-        sh = logging.StreamHandler(sys.stdout)
+    logger.configure(handlers=handlers)
-        sh.setFormatter(log_formatter)
-        LOG.addHandler(sh)
-        if imap_logger:
-            imap_logger.addHandler(sh)
 
 
 def setup_logging_no_config(loglevel, quiet):

aprsd/log/rich.py

@@ -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

requirements.in

@@ -37,3 +37,4 @@ shellingham
 geopy
 rush
 dataclasses-json
+loguru

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