]> git.ipfire.org Git - thirdparty/knot-resolver.git/commitdiff
manager: configurable logging
authorVasek Sraier <git@vakabus.cz>
Wed, 1 Dec 2021 16:48:08 +0000 (17:48 +0100)
committerAleš Mrázek <ales.mrazek@nic.cz>
Fri, 8 Apr 2022 14:17:53 +0000 (16:17 +0200)
- on startup, we are logging into a memory buffer (flushed to stderr in case of an error)
- after loading the first configuration file, we reconfigure logging such that it follows the config

closes #25

manager/etc/knot-resolver/config.dev.yml
manager/knot_resolver_manager/__main__.py
manager/knot_resolver_manager/config_store.py
manager/knot_resolver_manager/log.py [new file with mode: 0644]
manager/knot_resolver_manager/server.py
manager/knot_resolver_manager/utils/modelling.py
manager/poetry.lock
manager/pyproject.toml
manager/tests/unit/test_config_store.py [new file with mode: 0644]
manager/tests/unit/utils/test_modeling.py

index ee873a642bddb1a7d36c7a6808a74d86dd2b23f2..074097e822d965ab6b2a5de7f8bcd6341895911a 100644 (file)
@@ -2,6 +2,8 @@ cache:
   storage: ../cache
 logging:
   level: debug
+  groups:
+    - manager
 network:
   interfaces:
     - listen:
index 527785035e174ba48c5716c7cfcc52fdf1dfa0cf..9fde938f8b8468cdc69d0566973491f40ee9383c 100644 (file)
@@ -1,4 +1,3 @@
-import logging
 import sys
 from pathlib import Path
 from typing import Optional
@@ -6,8 +5,9 @@ from typing import Optional
 import click
 
 from knot_resolver_manager import compat
-from knot_resolver_manager.constants import DEFAULT_MANAGER_CONFIG_FILE, STARTUP_LOG_LEVEL
+from knot_resolver_manager.constants import DEFAULT_MANAGER_CONFIG_FILE
 from knot_resolver_manager.kresd_controller import list_controller_names
+from knot_resolver_manager.log import logger_startup
 from knot_resolver_manager.server import start_server
 
 
@@ -45,5 +45,8 @@ def main(config: Optional[str], list_backends: bool):
 
 
 if __name__ == "__main__":
-    logging.basicConfig(level=STARTUP_LOG_LEVEL)
+    # initial logging is to memory until we read the config
+    logger_startup()
+
+    # run the main
     main()  # pylint: disable=no-value-for-parameter
index ef67d00b50ba56b9f1f253f038fe6fe218ecd671..6b68db6be492b5e850b8dadad5453be9284bfddc 100644 (file)
@@ -1,6 +1,6 @@
 import asyncio
 from asyncio import Lock
-from typing import Awaitable, Callable, List, Tuple
+from typing import Any, Awaitable, Callable, List, Tuple
 
 from knot_resolver_manager.datamodel import KresConfig
 from knot_resolver_manager.exceptions import DataException, KresdManagerException
@@ -51,3 +51,24 @@ class ConfigStore:
 
     def get(self) -> KresConfig:
         return self._config
+
+
+def only_on_real_changes(selector: Callable[[KresConfig], Any]) -> Callable[[UpdateCallback], UpdateCallback]:
+    def decorator(orig_func: UpdateCallback) -> UpdateCallback:
+        original_value_set: Any = False
+        original_value: Any = None
+
+        async def new_func(config: KresConfig):
+            nonlocal original_value_set
+            nonlocal original_value
+            if not original_value_set:
+                original_value_set = True
+                original_value = selector(config)
+                await orig_func(config)
+            elif original_value != selector(config):
+                original_value = selector(config)
+                await orig_func(config)
+
+        return new_func
+
+    return decorator
diff --git a/manager/knot_resolver_manager/log.py b/manager/knot_resolver_manager/log.py
new file mode 100644 (file)
index 0000000..53d2f97
--- /dev/null
@@ -0,0 +1,83 @@
+import logging
+import logging.handlers
+import sys
+from typing import Optional
+
+from knot_resolver_manager.config_store import ConfigStore, only_on_real_changes
+from knot_resolver_manager.constants import STARTUP_LOG_LEVEL
+from knot_resolver_manager.datamodel.config_schema import KresConfig
+from knot_resolver_manager.datamodel.logging_config import LogTargetEnum
+
+logger = logging.getLogger(__name__)
+
+
+async def _set_log_level(config: KresConfig):
+    levels_map = {
+        "crit": "CRITICAL",
+        "err": "ERROR",
+        "warning": "WARNING",
+        "notice": "WARNING",
+        "info": "INFO",
+        "debug": "DEBUG",
+    }
+
+    # when logging is configured but not for us, still log all WARNING
+    if config.logging.groups and "manager" not in config.logging.groups:
+        target = "WARNING"
+    # otherwise, follow the standard log level
+    else:
+        target = levels_map[config.logging.level]
+
+    # expect exactly one existing log handler on the root
+    logger.warning(f"Changing logging level to '{target}'")
+    logging.getLogger().setLevel(target)
+
+
+async def _set_logging_handler(config: KresConfig):
+    target: Optional[LogTargetEnum] = config.logging.target
+
+    if target is None:
+        target = "stdout"
+
+    if target == "syslog":
+        handler = logging.handlers.SysLogHandler(address="/dev/log")
+        handler.setFormatter(logging.Formatter("%(name)s:%(message)s"))
+    elif target == "stdout":
+        handler = logging.StreamHandler(sys.stdout)
+        handler.setFormatter(logging.Formatter(logging.BASIC_FORMAT))
+    elif target == "stderr":
+        handler = logging.StreamHandler(sys.stderr)
+        handler.setFormatter(logging.Formatter(logging.BASIC_FORMAT))
+    else:
+        raise RuntimeError(f"Unexpected value '{target}' for log target in the config")
+
+    root = logging.getLogger()
+
+    # if we had a MemoryHandler before, we should give it the new handler where we can flush it
+    if isinstance(root.handlers[0], logging.handlers.MemoryHandler):
+        root.handlers[0].setTarget(handler)
+
+    # stop the old handler
+    root.handlers[0].flush()
+    root.handlers[0].close()
+    root.removeHandler(root.handlers[0])
+
+    # configure the new handler
+    root.addHandler(handler)
+
+
+@only_on_real_changes(lambda config: config.logging)
+async def _configure_logger(config: KresConfig):
+    await _set_logging_handler(config)
+    await _set_log_level(config)
+
+
+async def logger_init(config_store: ConfigStore):
+    await config_store.register_on_change_callback(_configure_logger)
+
+
+def logger_startup():
+    logging.getLogger().setLevel(STARTUP_LOG_LEVEL)
+    err_handler = logging.StreamHandler(sys.stderr)
+    err_handler.setFormatter(logging.Formatter(logging.BASIC_FORMAT))
+    logging.getLogger().addHandler(logging.handlers.MemoryHandler(10_000, logging.ERROR, err_handler))
index 9308a42d3227e5e5783864de3abebba8edfb33d1..c06075ad558b2079008e222ef671501644b01ebd 100644 (file)
@@ -13,6 +13,7 @@ from aiohttp.web_app import Application
 from aiohttp.web_response import json_response
 from aiohttp.web_runner import AppRunner, TCPSite, UnixSite
 
+from knot_resolver_manager import log
 from knot_resolver_manager.config_store import ConfigStore
 from knot_resolver_manager.constants import DEFAULT_MANAGER_CONFIG_FILE
 from knot_resolver_manager.datamodel.config_schema import KresConfig
@@ -69,12 +70,9 @@ class Server:
         self.site: Union[NoneType, TCPSite, UnixSite] = None
         self.listen_lock = asyncio.Lock()
 
-        self.log_level = "dummy"
-
         self.shutdown_event = asyncio.Event()
 
     async def _reconfigure(self, config: KresConfig):
-        self._set_log_level(config)
         await self._reconfigure_listen_address(config)
 
     async def _deny_listen_address_changes(self, config_old: KresConfig, config_new: KresConfig) -> Result[None, str]:
@@ -160,29 +158,6 @@ class Server:
             content_type="text/html",
         )
 
-    def _set_log_level(self, config: KresConfig):
-
-        levels_map = {
-            "crit": "CRITICAL",
-            "err": "ERROR",
-            "warning": "WARNING",
-            "notice": "WARNING",
-            "info": "INFO",
-            "debug": "DEBUG",
-        }
-
-        target = levels_map[config.logging.level]
-        if config.logging.groups and "manager" in config.logging.groups:
-            target = "DEBUG"
-
-        if self.log_level != target:
-            # expects one existing log handler on the root
-            h = logging.getLogger().handlers
-            assert len(h) == 1
-            logger.warning(f"Changing logging level to '{target}'")
-            h[0].setLevel(target)
-            self.log_level = target
-
     async def _handler_stop(self, _request: web.Request) -> web.Response:
         """
         Route handler for shutting down the server (and whole manager)
@@ -336,6 +311,10 @@ async def start_server(config: Union[Path, ParsedTree, _DefaultSentinel] = _DEFA
         # add a check to the config store, which disallows changes.
         await config_store.register_verifier(_deny_working_directory_changes)
 
+        # Up to this point, we have been logging to memory buffer. But now, when we have the configuration loaded, we
+        # can flush the buffer into the proper place
+        await log.logger_init(config_store)
+
         # After we have loaded the configuration, we can start worring about subprocess management.
         manager = await _init_manager(config_store)
     except KresdManagerException as e:
index 1936ca0c4a1d0dd9111442bc1d6a77816334eb2f..391b695429d2370fb662f0314c1fb4d9d2ddcc63 100644 (file)
@@ -494,6 +494,18 @@ class SchemaNode:
         Validation procedure called after all field are assigned. Should throw a ValueError in case of failure.
         """
 
+    def __eq__(self, o: object) -> bool:
+        cls = self.__class__
+        if not isinstance(o, cls):
+            return False
+
+        annot = cls.__dict__.get("__annotations__", {})
+        for name in annot.keys():
+            if getattr(self, name) != getattr(o, name):
+                return False
+
+        return True
+
     @classmethod
     def json_schema(cls: Type["SchemaNode"], include_schema_definition: bool = True) -> Dict[Any, Any]:
         if cls._PREVIOUS_SCHEMA is not None:
index 21bf2c53d32a0458b7b63d39dc3c13c64076ad77..95ff6f0a0be0e55878b9c2095591ed9b5d1e04ad 100644 (file)
@@ -546,6 +546,20 @@ wcwidth = "*"
 checkqa-mypy = ["mypy (==v0.761)"]
 testing = ["argcomplete", "hypothesis (>=3.56)", "mock", "nose", "requests", "xmlschema"]
 
+[[package]]
+name = "pytest-asyncio"
+version = "0.16.0"
+description = "Pytest support for asyncio."
+category = "dev"
+optional = false
+python-versions = ">= 3.6"
+
+[package.dependencies]
+pytest = ">=5.4.0"
+
+[package.extras]
+testing = ["coverage", "hypothesis (>=5.7.1)"]
+
 [[package]]
 name = "pytest-cov"
 version = "2.12.1"
@@ -889,7 +903,7 @@ testing = ["pytest (>=4.6)", "pytest-checkdocs (>=2.4)", "pytest-flake8", "pytes
 [metadata]
 lock-version = "1.1"
 python-versions = "^3.6.8"
-content-hash = "11ef244b43fbde5900250bb7b5af33f2c1f9171b5a641dd990ddf49f610a1819"
+content-hash = "0eba1cf028e34cf471c63cb4c3af81dbfa61f0f9f4b8fdc2835d1cab0a7913ca"
 
 [metadata.files]
 aiohttp = [
@@ -1309,6 +1323,10 @@ pytest = [
     {file = "pytest-5.4.3-py3-none-any.whl", hash = "sha256:5c0db86b698e8f170ba4582a492248919255fcd4c79b1ee64ace34301fb589a1"},
     {file = "pytest-5.4.3.tar.gz", hash = "sha256:7979331bfcba207414f5e1263b5a0f8f521d0f457318836a7355531ed1a4c7d8"},
 ]
+pytest-asyncio = [
+    {file = "pytest-asyncio-0.16.0.tar.gz", hash = "sha256:7496c5977ce88c34379df64a66459fe395cd05543f0a2f837016e7144391fcfb"},
+    {file = "pytest_asyncio-0.16.0-py3-none-any.whl", hash = "sha256:5f2a21273c47b331ae6aa5b36087047b4899e40f03f18397c0e65fa5cca54e9b"},
+]
 pytest-cov = [
     {file = "pytest-cov-2.12.1.tar.gz", hash = "sha256:261ceeb8c227b726249b376b8526b600f38667ee314f910353fa318caa01f4d7"},
     {file = "pytest_cov-2.12.1-py2.py3-none-any.whl", hash = "sha256:261bb9e47e65bd099c89c3edf92972865210c36813f80ede5277dceb77a4a62a"},
index 094551b7dc1c51ca2ac36838ba681dc69826847b..ee28de1f8e92b3778176c9f94410ce05c47b5127 100644 (file)
@@ -34,6 +34,7 @@ debugpy = "^1.2.1"
 Sphinx = "^4.0.2"
 supervisor = "^4.2.2"
 pylint = "^2.11.1"
+pytest-asyncio = "^0.16.0"
 
 [tool.poe.tasks]
 run = { cmd = "scripts/run", help = "Run the manager" }
diff --git a/manager/tests/unit/test_config_store.py b/manager/tests/unit/test_config_store.py
new file mode 100644 (file)
index 0000000..8feaa73
--- /dev/null
@@ -0,0 +1,31 @@
+import pytest
+
+from knot_resolver_manager.config_store import ConfigStore, only_on_real_changes
+from knot_resolver_manager.datamodel.config_schema import KresConfig
+
+
+@pytest.mark.asyncio  # type: ignore
+async def test_only_once():
+    count = 0
+
+    @only_on_real_changes(lambda config: config.logging.level)
+    async def change_callback(config: KresConfig):
+        nonlocal count
+        count += 1
+
+    config = KresConfig()
+    store = ConfigStore(config)
+
+    await store.register_on_change_callback(change_callback)
+    assert count == 1
+
+    config = KresConfig()
+    config.logging.level = "crit"
+    await store.update(config)
+    assert count == 2
+
+    config = KresConfig()
+    config.lua.script_only = True
+    config.lua.script = "meaningless value"
+    await store.update(config)
+    assert count == 2
index 6881261aed7303b788e1b3ff4a1a330d968d239e..6b76865813a8141c18165531c110de24eb48a044 100644 (file)
@@ -183,3 +183,21 @@ def test_partial_mutations():
     # raise validation SchemaException
     with raises(SchemaException):
         o = ConfSchema(d.update("/", parse_json('{"workers": -5}')))
+
+
+def test_eq():
+    class A(SchemaNode):
+        field: int
+
+    class B(SchemaNode):
+        a: A
+        field: str
+
+    b1 = B({"a": {"field": 6}, "field": "val"})
+    b2 = B({"a": {"field": 6}, "field": "val"})
+    b_diff = B({"a": {"field": 7}, "field": "val"})
+
+    assert b1 == b2
+    assert b2 != b_diff
+    assert b1 != b_diff
+    assert b_diff == b_diff