This is an automated email from the ASF dual-hosted git repository.
sbp pushed a commit to branch main
in repository https://gitbox.apache.org/repos/asf/tooling-trusted-release.git
The following commit(s) were added to refs/heads/main by this push:
new 6934fe7 Use structured, asynchronous logging for the storage audit log
6934fe7 is described below
commit 6934fe757a2f26d321a0d7442f81e964747516c5
Author: Sean B. Palmer <s...@miscoranda.com>
AuthorDate: Tue Aug 5 16:49:25 2025 +0100
Use structured, asynchronous logging for the storage audit log
---
atr/config.py | 4 +--
atr/log.py | 68 ++++++++++++++++++++++++-------------------
atr/server.py | 18 +++++++-----
atr/storage/__init__.py | 19 ++++++++----
atr/storage/types.py | 5 ++++
atr/storage/writers/checks.py | 19 ++++++++++--
atr/storage/writers/tokens.py | 6 ++++
7 files changed, 91 insertions(+), 48 deletions(-)
diff --git a/atr/config.py b/atr/config.py
index 60f5500..4c36173 100644
--- a/atr/config.py
+++ b/atr/config.py
@@ -61,7 +61,7 @@ class AppConfig:
# TODO: We need to get Puppet to check SVN out initially, or do it manually
SVN_STORAGE_DIR = os.path.join(STATE_DIR, "svn")
SQLITE_DB_PATH = decouple.config("SQLITE_DB_PATH", default="atr.db")
- AUDIT_LOG_FILE = os.path.join(STATE_DIR, "audit.log")
+ STORAGE_AUDIT_LOG_FILE = os.path.join(STATE_DIR, "storage-audit.log")
# Apache RAT configuration
APACHE_RAT_JAR_PATH = decouple.config("APACHE_RAT_JAR_PATH",
default="/opt/tools/apache-rat-0.16.1.jar")
@@ -132,7 +132,7 @@ def get() -> type[AppConfig]:
(config.FINISHED_STORAGE_DIR, "FINISHED_STORAGE_DIR"),
(config.UNFINISHED_STORAGE_DIR, "UNFINISHED_STORAGE_DIR"),
(config.SVN_STORAGE_DIR, "SVN_STORAGE_DIR"),
- (config.AUDIT_LOG_FILE, "AUDIT_LOG_FILE"),
+ (config.STORAGE_AUDIT_LOG_FILE, "STORAGE_AUDIT_LOG_FILE"),
]
relative_paths = [
(config.SQLITE_DB_PATH, "SQLITE_DB_PATH"),
diff --git a/atr/log.py b/atr/log.py
index deffc99..3ebf608 100644
--- a/atr/log.py
+++ b/atr/log.py
@@ -22,6 +22,39 @@ import logging
from typing import Any
+def caller_name(depth: int = 1) -> str:
+ frame = inspect.currentframe()
+ for _ in range(depth + 1):
+ if frame is None:
+ break
+ frame = frame.f_back
+
+ if frame is None:
+ return __name__
+
+ module = frame.f_globals.get("__name__", "<unknown>")
+ func = frame.f_code.co_name
+
+ if func == "<module>":
+ # We're at the top level
+ return module
+
+ # Are we in a class?
+ # There is probably a better way to do this
+ cls_name = None
+ if "self" in frame.f_locals:
+ cls_name = frame.f_locals["self"].__class__.__name__
+ elif ("cls" in frame.f_locals) and isinstance(frame.f_locals["cls"], type):
+ cls_name = frame.f_locals["cls"].__name__
+
+ if cls_name:
+ name = f"{module}.{cls_name}.{func}"
+ else:
+ name = f"{module}.{func}"
+
+ return name
+
+
def critical(msg: str, *args: Any, **kwargs: Any) -> None:
_event(logging.CRITICAL, msg, *args, **kwargs)
@@ -43,6 +76,10 @@ def info(msg: str, *args: Any, **kwargs: Any) -> None:
_event(logging.INFO, msg, *args, **kwargs)
+def interface_name(depth: int = 1) -> str:
+ return caller_name(depth=depth)
+
+
def log(level: int, msg: str, *args: Any, **kwargs: Any) -> None:
# Custom log level
_event(level, msg, *args, **kwargs)
@@ -53,36 +90,7 @@ def warning(msg: str, *args: Any, **kwargs: Any) -> None:
def _caller_logger(depth: int = 1) -> logging.Logger:
- frame = inspect.currentframe()
- for _ in range(depth + 1):
- if frame is None:
- break
- frame = frame.f_back
-
- if frame is None:
- return logging.getLogger(__name__)
-
- module = frame.f_globals.get("__name__", "<unknown>")
- func = frame.f_code.co_name
-
- if func == "<module>":
- # We're at the top level
- return logging.getLogger(module)
-
- # Are we in a class?
- # There is probably a better way to do this
- cls_name = None
- if "self" in frame.f_locals:
- cls_name = frame.f_locals["self"].__class__.__name__
- elif ("cls" in frame.f_locals) and isinstance(frame.f_locals["cls"], type):
- cls_name = frame.f_locals["cls"].__name__
-
- if cls_name:
- name = f"{module}.{cls_name}.{func}"
- else:
- name = f"{module}.{func}"
-
- return logging.getLogger(name)
+ return logging.getLogger(caller_name(depth))
def _event(level: int, msg: str, *args: Any, stacklevel: int = 3, **kwargs:
Any) -> None:
diff --git a/atr/server.py b/atr/server.py
index b0f72ec..5af5811 100644
--- a/atr/server.py
+++ b/atr/server.py
@@ -226,20 +226,24 @@ def app_setup_logging(app: base.QuartApp, config_mode:
config.Mode, app_config:
# Configure dedicated audit logger
try:
audit_handler = logging.FileHandler(
- app_config.AUDIT_LOG_FILE,
+ app_config.STORAGE_AUDIT_LOG_FILE,
encoding="utf-8",
mode="a",
)
- audit_handler.setFormatter(
- logging.Formatter(
- "%(asctime)s %(message)s",
- datefmt="%Y-%m-%dT%H:%M:%SZ",
- )
- )
+ # audit_handler.setFormatter(
+ # logging.Formatter("%(message)s")
+ # )
+ audit_queue = queue.Queue(-1)
+ audit_listener = logging.handlers.QueueListener(audit_queue,
audit_handler)
+ audit_listener.start()
+ app.extensions["audit_listener"] = audit_listener
+
audit_logger = logging.getLogger("atr.storage.audit")
audit_logger.setLevel(logging.INFO)
audit_logger.addHandler(audit_handler)
audit_logger.propagate = False
+ audit_queue_handler = logging.handlers.QueueHandler(audit_queue)
+ audit_logger.handlers = [audit_queue_handler]
except Exception:
logging.getLogger(__name__).exception("Failed to configure audit
logger")
diff --git a/atr/storage/__init__.py b/atr/storage/__init__.py
index 7735ec2..eaa67e4 100644
--- a/atr/storage/__init__.py
+++ b/atr/storage/__init__.py
@@ -18,6 +18,8 @@
from __future__ import annotations
import contextlib
+import datetime
+import json
import logging
from typing import TYPE_CHECKING, Final
@@ -25,8 +27,7 @@ if TYPE_CHECKING:
from collections.abc import AsyncGenerator
import atr.db as db
-
-# import atr.log as log
+import atr.log as log
import atr.models.sql as sql
import atr.principal as principal
import atr.storage.readers as readers
@@ -39,8 +40,14 @@ import atr.user as user
## Access credentials
-def audit(msg: str) -> None:
- msg = msg.replace("\n", " / ")
+# Do not rename this interface
+# It is named to reserve the atr.storage.audit logger name
+def audit(**kwargs: types.JSON) -> None:
+ now =
datetime.datetime.now(datetime.UTC).isoformat(timespec="milliseconds")
+ now = now.replace("+00:00", "Z")
+ action = log.caller_name()
+ kwargs = {"datetime": now, "action": action, **kwargs}
+ msg = json.dumps(kwargs, allow_nan=False)
# The atr.log logger should give the same name
# But to be extra sure, we set it manually
logger = logging.getLogger("atr.storage.audit")
@@ -48,8 +55,8 @@ def audit(msg: str) -> None:
class AccessCredentials:
- def audit_worthy_event(self, msg: str) -> None:
- audit(msg)
+ def log_auditable_event(self, **kwargs: types.JSON) -> None:
+ audit(**kwargs)
class AccessCredentialsRead(AccessCredentials): ...
diff --git a/atr/storage/types.py b/atr/storage/types.py
index 6461bba..8acf7ea 100644
--- a/atr/storage/types.py
+++ b/atr/storage/types.py
@@ -226,6 +226,11 @@ class Outcomes[T, E: Exception = Exception]:
self.__outcomes[i] = OutcomeResult[T](result, outcome.name)
+# TODO: Or we could use pydantic.types.JsonValue
+# Also this should be moved to models, so that the client can also use it
+type JSON = None | bool | int | float | str | list[JSON] | dict[str, JSON]
+
+
@dataclasses.dataclass
class CheckResults:
primary_results_list: list[sql.CheckResult]
diff --git a/atr/storage/writers/checks.py b/atr/storage/writers/checks.py
index 1ef3140..3a7bf68 100644
--- a/atr/storage/writers/checks.py
+++ b/atr/storage/writers/checks.py
@@ -23,6 +23,7 @@ import datetime
import sqlmodel
import atr.db as db
+import atr.log as log
import atr.models.sql as sql
import atr.storage as storage
@@ -107,13 +108,21 @@ class CommitteeMember(CommitteeParticipant):
)
self.__data.add(cri)
await self.__data.commit()
- self.__credentials.audit_worthy_event(f"Added check result ignore
{cri}")
+ self.__credentials.log_auditable_event(
+ action=log.interface_name(),
+ asf_uid=self.__asf_uid,
+ cri=cri.model_dump_json(exclude_none=True),
+ )
async def ignore_delete(self, id: int) -> None:
via = sql.validate_instrumented_attribute
await
self.__data.execute(sqlmodel.delete(sql.CheckResultIgnore).where(via(sql.CheckResultIgnore.id)
== id))
await self.__data.commit()
- self.__credentials.audit_worthy_event(f"Deleted check result ignore
{id} by {self.__asf_uid}")
+ self.__credentials.log_auditable_event(
+ action=log.interface_name(),
+ asf_uid=self.__asf_uid,
+ ignore_id=id,
+ )
async def ignore_update(
self,
@@ -139,4 +148,8 @@ class CommitteeMember(CommitteeParticipant):
cri.status = status
cri.message_glob = message_glob
await self.__data.commit()
- self.__credentials.audit_worthy_event(f"Updated check result ignore
{cri} by {self.__asf_uid}")
+ self.__credentials.log_auditable_event(
+ action=log.interface_name(),
+ asf_uid=self.__asf_uid,
+ cri=cri.model_dump_json(exclude_none=True),
+ )
diff --git a/atr/storage/writers/tokens.py b/atr/storage/writers/tokens.py
index e503386..288f3b3 100644
--- a/atr/storage/writers/tokens.py
+++ b/atr/storage/writers/tokens.py
@@ -25,6 +25,7 @@ import sqlmodel
import atr.db as db
import atr.jwtoken as jwtoken
+import atr.log as log
import atr.models.sql as sql
import atr.storage as storage
@@ -82,6 +83,11 @@ class FoundationCommitter(GeneralPublic):
issued_jwt = jwtoken.issue(self.__asf_uid)
pat.last_used = datetime.datetime.now(datetime.UTC)
await self.__data.commit()
+ self.__credentials.log_auditable_event(
+ action=log.interface_name(),
+ asf_uid=self.__asf_uid,
+ pat_hash=pat_hash,
+ )
return issued_jwt
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscr...@tooling.apache.org
For additional commands, e-mail: commits-h...@tooling.apache.org
