chore: copyright update

In the most cases it was enough to just add lock. In case of worker
trigger, since there is atomic operation on timer, it was also required
to add queue (coz python doesn't have atomics)

docs/ahriman.core.log.rst

@@ -4,6 +4,14 @@ ahriman.core.log package
 Submodules
 ----------
 
+ahriman.core.log.filtered\_access\_logger module
+------------------------------------------------
+
+.. automodule:: ahriman.core.log.filtered_access_logger
+   :members:
+   :no-undoc-members:
+   :show-inheritance:
+
 ahriman.core.log.http\_log\_handler module
 ------------------------------------------
 

docs/architecture.rst

@@ -41,7 +41,7 @@ This package contains everything required for the most of application actions an
 * ``ahriman.core.formatters`` package provides ``Printer`` sub-classes for printing data (e.g. package properties) to stdout which are used by some handlers.
 * ``ahriman.core.gitremote`` is a package with remote PKGBUILD triggers. Should not be called directly.
 * ``ahriman.core.http`` package provides HTTP clients which can be used later by other classes.
-* ``ahriman.core.log`` is a log utils package. It includes logger loader class, custom HTTP based logger and some wrappers.
+* ``ahriman.core.log`` is a log utils package. It includes logger loader class, custom HTTP based logger and access logger for HTTP services with additional filters.
 * ``ahriman.core.report`` is a package with reporting triggers. Should not be called directly.
 * ``ahriman.core.repository`` contains several traits and base repository (``ahriman.core.repository.Repository`` class) implementation.
 * ``ahriman.core.sign`` package provides sign feature (only gpg calls are available).

docs/configuration.rst

@@ -111,7 +111,7 @@ Reporting to web service related settings. In most cases there is fallback to we
 * ``enabled`` - enable reporting to web service, boolean, optional, default ``yes`` for backward compatibility.
 * ``address`` - remote web service address with protocol, string, optional. In case of websocket, the ``http+unix`` scheme and url encoded address (e.g. ``%2Fvar%2Flib%2Fahriman`` for ``/var/lib/ahriman``) must be used, e.g. ``http+unix://%2Fvar%2Flib%2Fahriman%2Fsocket``. In case if none set, it will be guessed from ``web`` section.
 * ``password`` - password to authorize in web service in order to update service status, string, required in case if authorization enabled.
-* ``suppress_http_log_errors`` - suppress HTTP log errors, boolean, optional, default ``no``. If set to ``yes``, any HTTP log errors (e.g. if web server is not available, but HTTP logging is enabled) will be suppressed.
+* ``suppress_http_log_errors`` - suppress http log errors, boolean, optional, default ``no``. If set to ``yes``, any http log errors (e.g. if web server is not available, but http logging is enabled) will be suppressed.
 * ``timeout`` - HTTP request timeout in seconds, integer, optional, default is ``30``.
 * ``username`` - username to authorize in web service in order to update service status, string, required in case if authorization enabled.
 

package/share/ahriman/settings/ahriman.ini.d/logging.ini

@@ -36,7 +36,7 @@ level = DEBUG
 qualname = root
 
 [logger_http]
-level = WARNING
+level = DEBUG
 qualname = http
 propagate = 0
 

src/ahriman/core/distributed/distributed_system.py

@@ -51,7 +51,7 @@ class DistributedSystem(Trigger, WebClient):
                 "time_to_live": {
                     "type": "integer",
                     "coerce": "integer",
-                    "min": 1,
+                    "min": 0,
                 },
             },
         },

src/ahriman/core/distributed/worker_trigger.py

@@ -61,31 +61,28 @@ class WorkerTrigger(DistributedSystem):
         """
         trigger action which will be called at the start of the application
         """
-        self.logger.info("registering instance %s in %s", self.worker, self.address)
+        self.logger.info("registering instance %s at %s", self.worker, self.address)
-        with self._lock:
+        self.create_timer()
-            self.create_timer()
 
     def on_stop(self) -> None:
         """
         trigger action which will be called before the stop of the application
         """
-        self.logger.info("removing instance %s in %s", self.worker, self.address)
+        self.logger.info("removing instance %s at %s", self.worker, self.address)
         with self._lock:
-            current_timers = self._timers.copy()  # will be used later
+            for timer in self._timers:
-            self._timers.clear()  # clear timer list
+                timer.cancel()  # cancel running timers
-
+            self._timers.clear()  # clear queue
-        for timer in current_timers:
-            timer.cancel()  # cancel remaining timers
 
     def ping(self) -> None:
         """
         register itself as alive worker and update the timer
         """
         with self._lock:
-            if not self._timers:  # make sure that there is related specific timer
+            try:
-                return
+                self._timers.popleft()  # make sure that we have something to pull
 
-            self._timers.popleft()  # pop first timer
+                self.register()
-
+                self.create_timer()
-            self.register()
+            except IndexError:
-            self.create_timer()
+                self.logger.warning("trigger is terminated, shutdown update cycle")

src/ahriman/core/log/filtered_access_logger.py

@@ -0,0 +1,108 @@
+#
+# Copyright (c) 2021-2024 ahriman team.
+#
+# This file is part of ahriman
+# (see https://github.com/arcan1s/ahriman).
+#
+# This program is free software: you can redistribute it and/or modify
+# it under the terms of the GNU General Public License as published by
+# the Free Software Foundation, either version 3 of the License, or
+# (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU General Public License for more details.
+#
+# You should have received a copy of the GNU General Public License
+# along with this program. If not, see <http://www.gnu.org/licenses/>.
+#
+import re
+
+from aiohttp.web import AccessLogger, BaseRequest, StreamResponse
+
+
+class FilteredAccessLogger(AccessLogger):
+    """
+    access logger implementation with log filter enabled
+
+    Attributes:
+        DISTRIBUTED_PATH_REGEX(str): (class attribute) regex used for distributed system uri
+        HEALTH_PATH_REGEX(re.Pattern): (class attribute) regex for health check endpoint
+        LOG_PATH_REGEX(re.Pattern): (class attribute) regex for logs uri
+        PROCESS_PATH_REGEX(re.Pattern): (class attribute) regex for process uri
+    """
+
+    DISTRIBUTED_PATH_REGEX = "/api/v1/distributed"
+    HEALTH_PATH_REGEX = "/api/v1/info"
+    LOG_PATH_REGEX = re.compile(r"^/api/v1/packages/[^/]+/logs$")
+    # technically process id is uuid, but we might change it later
+    PROCESS_PATH_REGEX = re.compile(r"^/api/v1/service/process/[^/]+$")
+
+    @staticmethod
+    def is_distributed_post(request: BaseRequest) -> bool:
+        """
+        check if the request is for distributed services ping
+
+        Args:
+            request(BaseRequest): http reqeust descriptor
+
+        Returns:
+            bool: True in case if request is distributed service ping endpoint and False otherwise
+        """
+        return request.method == "POST" and FilteredAccessLogger.DISTRIBUTED_PATH_REGEX == request.path
+
+    @staticmethod
+    def is_info_get(request: BaseRequest) -> bool:
+        """
+        check if the request is for health check
+
+        Args:
+            request(BaseRequest): http reqeust descriptor
+
+        Returns:
+            bool: True in case if request is health check and false otherwise
+        """
+        return request.method == "GET" and FilteredAccessLogger.HEALTH_PATH_REGEX == request.path
+
+    @staticmethod
+    def is_logs_post(request: BaseRequest) -> bool:
+        """
+        check if request looks like logs posting
+
+        Args:
+            request(BaseRequest): http reqeust descriptor
+
+        Returns:
+            bool: True in case if request looks like logs positing and False otherwise
+        """
+        return request.method == "POST" and FilteredAccessLogger.LOG_PATH_REGEX.match(request.path) is not None
+
+    @staticmethod
+    def is_process_get(request: BaseRequest) -> bool:
+        """
+        check if request looks like process status request
+
+        Args:
+            request(BaseRequest): http reqeust descriptor
+
+        Returns:
+            bool: True in case if request looks like process status request and False otherwise
+        """
+        return request.method == "GET" and FilteredAccessLogger.PROCESS_PATH_REGEX.match(request.path) is not None
+
+    def log(self, request: BaseRequest, response: StreamResponse, time: float) -> None:
+        """
+        access log with enabled filter by request path
+
+        Args:
+            request(BaseRequest): http reqeust descriptor
+            response(StreamResponse): streaming response object
+            time(float): log record timestamp
+        """
+        if self.is_distributed_post(request) \
+                or self.is_info_get(request) \
+                or self.is_logs_post(request) \
+                or self.is_process_get(request):
+            return
+        AccessLogger.log(self, request, response, time)

src/ahriman/web/web.py

@@ -29,6 +29,7 @@ from ahriman.core.configuration import Configuration
 from ahriman.core.database import SQLite
 from ahriman.core.distributed import WorkersCache
 from ahriman.core.exceptions import InitializeError
+from ahriman.core.log.filtered_access_logger import FilteredAccessLogger
 from ahriman.core.spawn import Spawn
 from ahriman.core.status.watcher import Watcher
 from ahriman.models.repository_id import RepositoryId
@@ -121,7 +122,7 @@ def run_server(application: Application) -> None:
     unix_socket = _create_socket(configuration, application)
 
     run_app(application, host=host, port=port, sock=unix_socket, handle_signals=True,
-            access_log=logging.getLogger("http"))
+            access_log=logging.getLogger("http"), access_log_class=FilteredAccessLogger)
 
 
 def setup_server(configuration: Configuration, spawner: Spawn, repositories: list[RepositoryId]) -> Application:

tests/ahriman/core/log/conftest.py

@@ -0,0 +1,16 @@
+import logging
+import pytest
+
+from ahriman.core.log.filtered_access_logger import FilteredAccessLogger
+
+
+@pytest.fixture
+def filtered_access_logger() -> FilteredAccessLogger:
+    """
+    fixture for custom access logger
+
+    Returns:
+        FilteredAccessLogger: custom access logger test instance
+    """
+    logger = logging.getLogger()
+    return FilteredAccessLogger(logger)

tests/ahriman/core/log/test_filtered_access_logger.py

@@ -0,0 +1,136 @@
+from pytest_mock import MockerFixture
+from unittest.mock import MagicMock
+
+from ahriman.core.log.filtered_access_logger import FilteredAccessLogger
+
+
+def test_is_distributed_post() -> None:
+    """
+    must correctly define distributed services ping request
+    """
+    request = MagicMock()
+
+    request.method = "POST"
+    request.path = "/api/v1/distributed"
+    assert FilteredAccessLogger.is_distributed_post(request)
+
+    request.method = "GET"
+    request.path = "/api/v1/distributed"
+    assert not FilteredAccessLogger.is_distributed_post(request)
+
+    request.method = "POST"
+    request.path = "/api/v1/distributed/path"
+    assert not FilteredAccessLogger.is_distributed_post(request)
+
+
+def test_is_info_get() -> None:
+    """
+    must correctly define health check request
+    """
+    request = MagicMock()
+
+    request.method = "GET"
+    request.path = "/api/v1/info"
+    assert FilteredAccessLogger.is_info_get(request)
+
+    request.method = "POST"
+    request.path = "/api/v1/info"
+    assert not FilteredAccessLogger.is_info_get(request)
+
+    request.method = "GET"
+    request.path = "/api/v1/infos"
+    assert not FilteredAccessLogger.is_info_get(request)
+
+
+def test_is_logs_post() -> None:
+    """
+    must correctly define if request belongs to logs posting
+    """
+    request = MagicMock()
+
+    request.method = "POST"
+    request.path = "/api/v1/packages/ahriman/logs"
+    assert FilteredAccessLogger.is_logs_post(request)
+
+    request.method = "POST"
+    request.path = "/api/v1/packages/linux-headers/logs"
+    assert FilteredAccessLogger.is_logs_post(request)
+
+    request.method = "POST"
+    request.path = "/api/v1/packages/memtest86+/logs"
+    assert FilteredAccessLogger.is_logs_post(request)
+
+    request.method = "POST"
+    request.path = "/api/v1/packages/memtest86%2B/logs"
+    assert FilteredAccessLogger.is_logs_post(request)
+
+    request.method = "POST"
+    request.path = "/api/v1/packages/python2.7/logs"
+    assert FilteredAccessLogger.is_logs_post(request)
+
+    request.method = "GET"
+    request.path = "/api/v1/packages/ahriman/logs"
+    assert not FilteredAccessLogger.is_logs_post(request)
+
+    request.method = "POST"
+    request.path = "/api/v1/packages/ahriman"
+    assert not FilteredAccessLogger.is_logs_post(request)
+
+    request.method = "POST"
+    request.path = "/api/v1/packages/ahriman/logs/random/path/after"
+    assert not FilteredAccessLogger.is_logs_post(request)
+
+
+def test_is_process_get() -> None:
+    """
+    must correctly define if request belongs to process get
+    """
+    request = MagicMock()
+
+    request.method = "GET"
+    request.path = "/api/v1/service/process/e7d67119-264a-48f4-b7e4-07bc96a7de00"
+    assert FilteredAccessLogger.is_process_get(request)
+
+    request.method = "POST"
+    request.path = "/api/v1/service/process/e7d67119-264a-48f4-b7e4-07bc96a7de00"
+    assert not FilteredAccessLogger.is_process_get(request)
+
+    request.method = "GET"
+    request.path = "/api/v1/service/process/e7d67119-264a-48f4-b7e4-07bc96a7de00/some/random/path"
+    assert not FilteredAccessLogger.is_process_get(request)
+
+    request.method = "GET"
+    request.path = "/api/v1/service/process"
+    assert not FilteredAccessLogger.is_process_get(request)
+
+    request.method = "GET"
+    request.path = "/api/v1/service/process/"
+    assert not FilteredAccessLogger.is_process_get(request)
+
+
+def test_log(filtered_access_logger: FilteredAccessLogger, mocker: MockerFixture) -> None:
+    """
+    must emit log record
+    """
+    request_mock = MagicMock()
+    response_mock = MagicMock()
+    is_log_path_mock = mocker.patch("ahriman.core.log.filtered_access_logger.FilteredAccessLogger.is_logs_post",
+                                    return_value=False)
+    log_mock = mocker.patch("aiohttp.web_log.AccessLogger.log")
+
+    filtered_access_logger.log(request_mock, response_mock, 0.001)
+    is_log_path_mock.assert_called_once_with(request_mock)
+    log_mock.assert_called_once_with(filtered_access_logger, request_mock, response_mock, 0.001)
+
+
+def test_log_filter_logs(filtered_access_logger: FilteredAccessLogger, mocker: MockerFixture) -> None:
+    """
+    must skip log record in case if it is from logs posting
+    """
+    request_mock = MagicMock()
+    response_mock = MagicMock()
+    mocker.patch("ahriman.core.log.filtered_access_logger.FilteredAccessLogger.is_logs_post", return_value=True)
+    log_mock = mocker.patch("aiohttp.web_log.AccessLogger.log")
+
+    filtered_access_logger.log(request_mock, response_mock, 0.001)
+    log_mock.assert_not_called()

tests/ahriman/web/test_web.py

@@ -7,6 +7,7 @@ from unittest.mock import call as MockCall
 
 from ahriman.core.configuration import Configuration
 from ahriman.core.exceptions import InitializeError
+from ahriman.core.log.filtered_access_logger import FilteredAccessLogger
 from ahriman.core.spawn import Spawn
 from ahriman.core.status.watcher import Watcher
 from ahriman.web.keys import ConfigurationKey
@@ -103,7 +104,7 @@ def test_run(application: Application, mocker: MockerFixture) -> None:
     run_server(application)
     run_application_mock.assert_called_once_with(
         application, host="127.0.0.1", port=port, sock=None, handle_signals=True,
-        access_log=pytest.helpers.anyvar(int),
+        access_log=pytest.helpers.anyvar(int), access_log_class=FilteredAccessLogger
     )
 
 
@@ -118,7 +119,7 @@ def test_run_with_auth(application_with_auth: Application, mocker: MockerFixture
     run_server(application_with_auth)
     run_application_mock.assert_called_once_with(
         application_with_auth, host="127.0.0.1", port=port, sock=None, handle_signals=True,
-        access_log=pytest.helpers.anyvar(int),
+        access_log=pytest.helpers.anyvar(int), access_log_class=FilteredAccessLogger
     )
 
 
@@ -135,7 +136,7 @@ def test_run_with_socket(application: Application, mocker: MockerFixture) -> Non
     socket_mock.assert_called_once_with(application[ConfigurationKey], application)
     run_application_mock.assert_called_once_with(
         application, host="127.0.0.1", port=port, sock=42, handle_signals=True,
-        access_log=pytest.helpers.anyvar(int),
+        access_log=pytest.helpers.anyvar(int), access_log_class=FilteredAccessLogger
     )