Add support for python logging (#2969)

* adds log module

* enable logging in the app

* adds a getLogger method to AddonManager

* change log level depending on ANKIDEV

* fix undefined module variable

* - fix addons log file path
- remove a breakpoint leftover

set the addons log files under pm.addonFolder()/NNNNNN/user_files/logs/NNNNNN.log

* fix path bug

* move log closing handling into AddonManager deleteAddon/backupUserFiles methods

* logging module level import
fix undefined variable in backupUserFiles

* pretty format log records

* move MediaServer log into logging

* update CONTRIBUTORS

* documentation cleanup

* capture warnings into log messages
fix waitress verbosity

* remove record_factory function

* add get_logger method alias to getLogger in AddonManager
switch to TimedRotatingFileHandler handler
fix minor typo

* set main log level to DEBUG if ANKIDEV is not 0 (or unset)
added two new methods to AddonManager addon_get_logger/addon_toggle_log_level

* add new find_logger_output to AddonManager

* move logs under pm.base

* change log output

* update addonmanager getlogger

* Format imports

* Refactor logging set-up slightly and tweak docstring

* Remove obsolete log closing statements

As logs are no longer stored in user_files, we do not need to close their handlers

* Refactor and try to simplify log module

* Remove demo code

* Refactor and update add-on manager logging API

* Simplify writing unit tests for add-ons that use logging

Loggers are likely to be also employed in non UI code, so it seems like a good idea to decouple them from requiring a running Anki instance to work (thus freeing add-on authors from the need to mock Anki APIs in their tests).

* Fix arguments and drop obsolete inline instructions

Lets add a section on logging to the add-on docs instead

* Drop unnecessary import

* Supply logging basicConfig force option by default

Until we change the module import order and thus ensure that `log` is always evaluated before third-party dependencies have a chance to initialize the root logger, `force` is non-optional.

* Fix formatting and type errors

* Restore mediasrv type ignore comments

* Add note on prefix API stability

* Consistently use addon_from_module in new code

* Use logFolder rather than profileFolder

* Adjust method name for PEP8

* Change loggerDict access path, satisfying pylint

* Drop unused import and use lazy % formatting

* lint fix

* refactor .log_folder -> .addon_logs
store anki.log under logdir

* Fix method name (dae)

* Disable file-based logging in the backend (dae)

I have never found this useful, and it logs nothing by default, so
creating/opening the file is a waste. Removing it also ensures that
addon_logs() is solely used for add-ons.

---------

Co-authored-by: Glutanimate <5459332+glutanimate@users.noreply.github.com>

CONTRIBUTORS

@@ -157,8 +157,9 @@ Marko Sisovic <msisovic13@gmail.com>
 Viktor Ricci <ricci@primateer.de>
 Harvey Randall <harveyrandall2001@gmail.com>
 Pedro Lameiras <pedrolameiras@tecnico.ulisboa.pt>
-Kai Knoblich  <kai@FreeBSD.org>
+Kai Knoblich <kai@FreeBSD.org>
 Lucas Scharenbroch <lucasscharenbroch@gmail.com>
+Antonio Cavallo <a.cavallo@cavallinux.eu>
 
 ********************
 

pylib/anki/collection.py

@@ -133,9 +133,9 @@ class Collection(DeprecatedNamesMixin):
     sched: V3Scheduler | DummyScheduler
 
     @staticmethod
-    def initialize_backend_logging(path: str | None = None) -> None:
-        """Enable terminal and optional file-based logging. Must be called only once."""
-        RustBackend.initialize_logging(path)
+    def initialize_backend_logging() -> None:
+        """Enable terminal logging. Must be called only once."""
+        RustBackend.initialize_logging(None)
 
     def __init__(
         self,

qt/aqt/__init__.py

@@ -3,6 +3,7 @@
 
 from __future__ import annotations
 
+import logging
 import sys
 
 if sys.version_info[0] < 3 or sys.version_info[1] < 9:
@@ -41,6 +42,7 @@ import locale
 import os
 import tempfile
 import traceback
+from pathlib import Path
 from typing import TYPE_CHECKING, Any, Callable, Optional, cast
 
 import anki.lang
@@ -50,6 +52,7 @@ from anki.collection import Collection
 from anki.consts import HELP_SITE
 from anki.utils import checksum, is_lin, is_mac
 from aqt import gui_hooks
+from aqt.log import setup_logging
 from aqt.qt import *
 from aqt.utils import TR, tr
 
@@ -572,7 +575,6 @@ def _run(argv: Optional[list[str]] = None, exec: bool = True) -> Optional[AnkiAp
     pm = None
     try:
         base_folder = ProfileManager.get_created_base_folder(opts.base)
-        Collection.initialize_backend_logging(str(base_folder / "anki.log"))
 
         # default to specified/system language before getting user's preference so that we can localize some more strings
         lang = anki.lang.get_def_lang(opts.lang)
@@ -581,6 +583,8 @@ def _run(argv: Optional[list[str]] = None, exec: bool = True) -> Optional[AnkiAp
 
         pm = ProfileManager(base_folder)
         pmLoadResult = pm.setupMeta()
+
+        Collection.initialize_backend_logging()
     except:
         # will handle below
         traceback.print_exc()
@@ -623,6 +627,11 @@ def _run(argv: Optional[list[str]] = None, exec: bool = True) -> Optional[AnkiAp
         # we've signaled the primary instance, so we should close
         return None
 
+    setup_logging(
+        pm.addon_logs(),
+        level=logging.DEBUG if int(os.getenv("ANKIDEV", "0")) else logging.INFO,
+    )
+
     if not pm:
         if i18n_setup:
             QMessageBox.critical(

qt/aqt/addons.py

@@ -6,6 +6,7 @@ from __future__ import annotations
 import html
 import io
 import json
+import logging
 import os
 import re
 import zipfile
@@ -33,6 +34,7 @@ from anki.httpclient import HttpClient
 from anki.lang import without_unicode_isolation
 from anki.utils import int_version_to_str
 from aqt import gui_hooks
+from aqt.log import ADDON_LOGGER_PREFIX, find_addon_logger, get_addon_logs_folder
 from aqt.qt import *
 from aqt.utils import (
     askUser,
@@ -662,7 +664,11 @@ class AddonManager:
 
         return markdown.markdown(contents, extensions=[md_in_html.makeExtension()])
 
-    def addonFromModule(self, module: str) -> str:
+    def addonFromModule(self, module: str) -> str:  # softly deprecated
+        return module.split(".")[0]
+
+    @staticmethod
+    def addon_from_module(module: str) -> str:
         return module.split(".")[0]
 
     def configAction(self, module: str) -> Callable[[], bool | None]:
@@ -727,8 +733,9 @@ class AddonManager:
     def _userFilesBackupPath(self) -> str:
         return os.path.join(self.addonsFolder(), "files_backup")
 
-    def backupUserFiles(self, sid: str) -> None:
-        p = self._userFilesPath(sid)
+    def backupUserFiles(self, module: str) -> None:
+        p = self._userFilesPath(module)
+
         if os.path.exists(p):
             os.rename(p, self._userFilesBackupPath())
 
@@ -752,6 +759,38 @@ class AddonManager:
     def getWebExports(self, module: str) -> str:
         return self._webExports.get(module)
 
+    # Logging
+    ######################################################################
+
+    @classmethod
+    def get_logger(cls, module: str) -> logging.Logger:
+        """Return a logger for the given add-on module.
+
+        NOTE: This method is static to allow it to be called outside of a
+        running Anki instance, e.g. in add-on unit tests.
+        """
+        return logging.getLogger(
+            f"{ADDON_LOGGER_PREFIX}{cls.addon_from_module(module)}"
+        )
+
+    def has_logger(self, module: str) -> bool:
+        return find_addon_logger(self.addon_from_module(module)) is not None
+
+    def is_debug_logging_enabled(self, module: str) -> bool:
+        if not (logger := find_addon_logger(self.addon_from_module(module))):
+            return False
+        return logger.isEnabledFor(logging.DEBUG)
+
+    def toggle_debug_logging(self, module: str, enable: bool) -> None:
+        if not (logger := find_addon_logger(self.addon_from_module(module))):
+            return
+        logger.setLevel(logging.DEBUG if enable else logging.INFO)
+
+    def logs_folder(self, module: str) -> Path:
+        return get_addon_logs_folder(
+            self.mw.pm.addon_logs(), self.addon_from_module(module)
+        )
+
 
 # Add-ons Dialog
 ######################################################################

qt/aqt/log.py

@@ -0,0 +1,101 @@
+# Copyright: Ankitects Pty Ltd and contributors
+# License: GNU AGPL, version 3 or later; http://www.gnu.org/licenses/agpl.html
+
+from __future__ import annotations
+
+import logging
+import sys
+from logging.handlers import TimedRotatingFileHandler
+from pathlib import Path
+from typing import Optional, cast
+
+# All loggers with the following prefix will be treated as add-on loggers
+#
+# To instatiate a logger with this prefix, use aqt.AddonManager.get_logger()
+#
+# NOTE: Add-ons might also directly instantiate a logger with this prefix, e.g. in
+#       order to avoid depending on the Anki codebase, so this prefix should not
+#       be changed.
+ADDON_LOGGER_PREFIX = "addon."
+
+# Formatter used for all loggers
+FORMATTER = logging.Formatter("%(asctime)s:%(levelname)s:%(name)s: %(message)s")
+
+
+class AnkiLoggerManager(logging.Manager):
+    # inspired by: https://github.com/abdnh/ankiutils/blob/master/src/ankiutils/log.py
+
+    def __init__(
+        self,
+        logs_path: Path | str,
+        existing_loggers: dict[str, logging.Logger | logging.PlaceHolder],
+        rootnode: logging.RootLogger,
+    ):
+        super().__init__(rootnode)
+        self.loggerDict = existing_loggers
+        self.logs_path = Path(logs_path)
+
+    def getLogger(self, name: str) -> logging.Logger:
+        if not name.startswith(ADDON_LOGGER_PREFIX) or name in self.loggerDict:
+            return super().getLogger(name)
+
+        # Create a new add-on logger
+        logger = super().getLogger(name)
+
+        module = name.split(ADDON_LOGGER_PREFIX)[1].partition(".")[0]
+        path = get_addon_logs_folder(self.logs_path, module=module) / f"{module}.log"
+        path.parent.mkdir(parents=True, exist_ok=True)
+
+        # Keep the last 10 days of logs
+        handler = TimedRotatingFileHandler(
+            filename=path, when="D", interval=1, backupCount=10, encoding="utf-8"
+        )
+        handler.setFormatter(FORMATTER)
+
+        logger.addHandler(handler)
+
+        return logger
+
+
+def get_addon_logs_folder(logs_path: Path | str, module: str) -> Path:
+    return Path(logs_path) / "addons" / module
+
+
+def find_addon_logger(module: str) -> logging.Logger | None:
+    return cast(
+        Optional[logging.Logger],
+        logging.Logger.manager.loggerDict.get(f"{ADDON_LOGGER_PREFIX}{module}"),
+    )
+
+
+def setup_logging(path: Path | str, **kwargs) -> None:
+    """
+    Set up logging for the application.
+
+    Configures the root logger to output logs to stdout by default, with custom
+    handling for add-on logs. The add-on logs are saved to a separate folder and file
+    for each add-on, under the path provided.
+
+    Args:
+        path (Path): The path where the log files should be stored.
+        **kwargs: Arbitrary keyword arguments for logging.basicConfig
+    """
+
+    # Patch root logger manager to handle add-on loggers
+    logger_manager = AnkiLoggerManager(
+        path, existing_loggers=logging.Logger.manager.loggerDict, rootnode=logging.root
+    )
+    logging.Logger.manager = logger_manager
+
+    stdout_handler = logging.StreamHandler(stream=sys.stdout)
+    stdout_handler.setFormatter(FORMATTER)
+    logging.basicConfig(handlers=[stdout_handler], force=True, **kwargs)
+    logging.captureWarnings(True)
+
+    # Silence some loggers of external libraries:
+    silenced_loggers = [
+        "waitress.queue",
+    ]
+    for logger in silenced_loggers:
+        logging.getLogger(logger).setLevel(logging.CRITICAL)
+        logging.getLogger(logger).propagate = False

qt/aqt/mediasrv.py

@@ -10,7 +10,6 @@ import os
 import re
 import sys
 import threading
-import time
 import traceback
 from dataclasses import dataclass
 from errno import EPROTOTYPE
@@ -43,6 +42,7 @@ from aqt.utils import aqt_data_path, show_warning, tr
 # https://forums.ankiweb.net/t/anki-crash-when-using-a-specific-deck/22266
 waitress.wasyncore._DISCONNECTED = waitress.wasyncore._DISCONNECTED.union({EPROTOTYPE})  # type: ignore
 
+logger = logging.getLogger(__name__)
 app = flask.Flask(__name__, root_path="/fake")
 flask_cors.CORS(app, resources={r"/*": {"origins": "127.0.0.1"}})
 
@@ -98,11 +98,6 @@ class MediaServer(threading.Thread):
 
     def run(self) -> None:
         try:
-            if dev_mode:
-                # idempotent if logging has already been set up
-                logging.basicConfig()
-            logging.getLogger("waitress").setLevel(logging.ERROR)
-
             desired_host = os.getenv("ANKI_API_HOST", "127.0.0.1")
             desired_port = int(os.getenv("ANKI_API_PORT") or 0)
             self.server = create_server(
@@ -111,11 +106,11 @@ class MediaServer(threading.Thread):
                 port=desired_port,
                 clear_untrusted_proxy_headers=True,
             )
-            if dev_mode:
-                print(
-                    "Serving on http://%s:%s"
-                    % (self.server.effective_host, self.server.effective_port)  # type: ignore
-                )
+            logger.info(
+                "Serving on http://%s:%s",
+                self.server.effective_host,  # type: ignore[union-attr]
+                self.server.effective_port,  # type: ignore[union-attr]
+            )
 
             self._ready.set()
             self.server.run()
@@ -300,8 +295,7 @@ def handle_request(pathin: str) -> Response:
             abort(403)
 
     req = _extract_request(pathin)
-    if dev_mode:
-        print(f"{time.time():.3f} {flask.request.method} /{pathin}")
+    logger.debug("%s /%s", flask.request.method, pathin)
 
     if isinstance(req, NotFound):
         print(req.message)

qt/aqt/profiles.py

@@ -309,6 +309,9 @@ class ProfileManager:
     def collectionPath(self) -> str:
         return os.path.join(self.profileFolder(), "collection.anki2")
 
+    def addon_logs(self) -> str:
+        return self._ensureExists(os.path.join(self.base, "logs"))
+
     # Downgrade
     ######################################################################