Audit log formatter (distributed-system-analysis#3611)

dbutenhof · web-flow · commit 12710f114504 · 2024-03-07T08:04:29.000-05:00
* Audit log formatter

Another late night ops side project: this queries the `Audit` log with filters
and displays the results either in detail or summary, optionally with
pagination.

```
/opt/pbench-server/bin/pbench-audit --since 2024-02-29 --until 2024-03-01 --name upload --summary
[...]
[2024-02-29 19:35:07] upload uperf_HyperV_RHEL-9.4.0-20240225.8_x86_64_gen2_hv_netvsc_quick_D240227T172431_2024.02.27T09.24.31 FAILURE (legacy) [2.584 seconds]
[2024-02-29 19:36:09] upload uperf_HyperV_RHEL-9.4.0-20240225.8_x86_64_gen2_hv_netvsc_quick_D240227T172431_2024.02.27T09.24.31 SUCCESS (legacy) [4.093 seconds]
Reported 428 audit events:
         BEGIN        214
       SUCCESS         24
       FAILURE        190
```

Or (full form):

```
/opt/pbench-server/bin/pbench-audit -C /opt/pbench-server/lib/config/pbench-server.cfg --since 2024-02-29T12:00:00 --until '2024-02-29 19:00:00' --name upload
[...]
  [2024-02-29 18:58:09.608043+00:00] : upload BEGIN
    DATASET uperf_HyperV_RHEL-9.4.0-20240225.8_x86_64_gen2_hv_netvsc_quick_D240227T172431_2024.02.27T09.24.31 by user legacy
      {'access': 'public', 'metadata': {'global.server.legacy.version': '0.69.11', 'global.server.legacy.sha1': '29bf18093', 'global.server.legacy.hostname': 'n010.intlab.redhat.com'}}
  [2024-02-29 18:58:12.279230+00:00] : upload FAILURE [2.671 seconds]
    DATASET uperf_HyperV_RHEL-9.4.0-20240225.8_x86_64_gen2_hv_netvsc_quick_D240227T172431_2024.02.27T09.24.31 by user legacy
      {'message': "A tarball with the name 'uperf_HyperV_RHEL-9.4.0-20240225.8_x86_64_gen2_hv_netvsc_quick_D240227T172431_2024.02.27T09.24.31' already exists"}
  [2024-02-29 18:59:05.843728+00:00] : upload BEGIN
    DATASET uperf_HyperV_RHEL-9.4.0-20240225.8_x86_64_gen2_hv_netvsc_quick_D240227T172431_2024.02.27T09.24.31 by user legacy
      {'access': 'public', 'metadata': {'global.server.legacy.version': '0.69.11', 'global.server.legacy.sha1': '29bf18093', 'global.server.legacy.hostname': 'n010.intlab.redhat.com'}}
  [2024-02-29 18:59:08.592574+00:00] : upload FAILURE [2.749 seconds]
    DATASET uperf_HyperV_RHEL-9.4.0-20240225.8_x86_64_gen2_hv_netvsc_quick_D240227T172431_2024.02.27T09.24.31 by user legacy
      {'message': "A tarball with the name 'uperf_HyperV_RHEL-9.4.0-20240225.8_x86_64_gen2_hv_netvsc_quick_D240227T172431_2024.02.27T09.24.31' already exists"}
Reported 354 audit events:
         BEGIN        177
       SUCCESS         23
       FAILURE        154
```
diff --git a/lib/pbench/cli/server/audit.py b/lib/pbench/cli/server/audit.py
@@ -0,0 +1,187 @@
+from collections import defaultdict
+import datetime
+from typing import Iterator, Optional
+
+import click
+
+from pbench.cli import pass_cli_context
+from pbench.cli.server import config_setup, Verify
+from pbench.cli.server.options import common_options
+from pbench.server import BadConfig, OperationCode
+from pbench.server.database.database import Database
+from pbench.server.database.models.audit import Audit, AuditStatus, AuditType
+
+COLUMNS = (
+    "id",
+    "root_id",
+    "name",
+    "operation",
+    "object_type",
+    "object_id",
+    "object_name",
+    "user_id",
+    "user_name",
+    "status",
+    "reason",
+)
+
+verifier: Optional[Verify] = None
+
+
+def auditor(kwargs) -> Iterator[str]:
+    """Report audit records matching patterns.
+
+    Args:
+        kwargs: the command options.
+
+    Returns:
+        A sequence of lines to be written
+    """
+
+    summary = kwargs.get("summary")
+    open: dict[int, Audit] = {}
+    query = (
+        Database.db_session.query(Audit)
+        .order_by(Audit.timestamp)
+        .execution_options(stream_results=True)
+    )
+    filters = []
+    for k in COLUMNS:
+        if kwargs.get(k):
+            filters.append(getattr(Audit, k) == kwargs.get(k))
+    since = kwargs.get("since")
+    until = kwargs.get("until")
+    if since:
+        filters.append(Audit.timestamp >= since)
+    if until:
+        filters.append(Audit.timestamp <= until)
+    query = query.filter(*filters)
+    if not summary:
+        yield "Audit records:\n"
+    rows = query.yield_per(2000)
+    count = 0
+    status = defaultdict(int)
+    for audit in rows:
+        duration = ""
+        count += 1
+        status[audit.status] += 1
+
+        # If we're showing both start and termination events, we can compute
+        # the duration of an operation; so save "open" BEGIN event timestamps
+        # until we reach the matching termination (SUCCESS. FAILURE, WARNING).
+        if audit.status is AuditStatus.BEGIN:
+            open[audit.id] = audit
+        else:
+            if audit.root_id in open:
+                delta: datetime.timedelta = (
+                    audit.timestamp - open[audit.root_id].timestamp
+                )
+                d = float(delta.seconds) + (delta.microseconds / 1000000.0)
+                duration = f" [{d:.3f} seconds]"
+                del open[audit.root_id]
+        if summary:
+            if duration:
+                yield (
+                    f"[{audit.timestamp:%Y-%m-%d %H:%M:%S}] {audit.name} "
+                    f"{audit.object_name} {audit.status.name} ({audit.user_name}){duration}\n"
+                )
+            continue
+        yield f"  [{audit.timestamp}] : {audit.name} {audit.status.name}{duration}\n"
+        yield f"    {audit.object_type.name} {audit.object_name} by user {audit.user_name}\n"
+        if kwargs.get("ids"):
+            yield (
+                f"    ID {audit.id}, ROOT {audit.root_id}: OBJ "
+                f"{audit.object_id}, UID {audit.user_id}\n"
+            )
+        if audit.attributes:
+            yield f"      {audit.attributes}\n"
+    yield ""
+    yield f"Reported {count:,d} audit events:\n"
+    for s, c in status.items():
+        yield f"    {s.name:>10s} {c:>10,d}\n"
+    if open:
+        yield f"{len(open):,d} unterminated events:\n"
+        for audit in open.values():
+            yield (
+                f"  [{audit.timestamp:%Y-%m-%d %H:%M:%S}] {audit.id:10d} "
+                f"{audit.name} {audit.object_name} ({audit.user_name}) {audit.attributes}\n"
+            )
+
+
+@click.command(name="pbench-audit")
+@pass_cli_context
+@click.option(
+    "--ids",
+    default=False,
+    is_flag=True,
+    help="Show user and object IDs as well as names",
+)
+@click.option("--name", type=str, help="Select by audit event name")
+@click.option(
+    "--operation",
+    type=click.Choice([o.name for o in OperationCode], case_sensitive=False),
+    help="Select by audit operation name",
+)
+@click.option(
+    "--object-type",
+    type=click.Choice([t.name for t in AuditType], case_sensitive=False),
+    help="Select by object type",
+)
+@click.option("--object-id", type=str, help="Select by object ID")
+@click.option("--object-name", type=str, help="Select by object name")
+@click.option("--page", default=False, is_flag=True, help="Paginate the output")
+@click.option("--user-id", type=str, help="Select by user ID")
+@click.option("--user-name", type=str, help="Select by username")
+@click.option(
+    "--status",
+    type=click.Choice([s.name for s in AuditStatus], case_sensitive=False),
+    help="Select by operation status",
+)
+@click.option(
+    "--summary", default=False, is_flag=True, help="Show one-line summary of operations"
+)
+@click.option(
+    "--since",
+    type=click.DateTime(),
+    help="Select entries on or after specified date/time",
+)
+@click.option(
+    "--until",
+    type=click.DateTime(),
+    help="Select entries on or before specified date/time",
+)
+@click.option(
+    "--verify", "-v", default=False, is_flag=True, help="Display intermediate messages"
+)
+@common_options
+def audit(context: object, **kwargs):
+    """Query and format the audit DB table
+
+    The Audit table records a sequence of events representing all changes made
+    to the data controlled by the Pbench Server. This tool supports queries to
+    display audit events based on various search criteria including timestamp,
+    user, object identification, and others.
+    \f
+
+    Args:
+        context: click context
+        kwargs: click options
+    """
+    global verifier
+    verifier = Verify(kwargs.get("verify"))
+
+    try:
+        config_setup(context)
+        if kwargs.get("page"):
+            click.echo_via_pager(auditor(kwargs))
+        else:
+            for line in auditor(kwargs):
+                click.echo(line, nl=False)
+        rv = 0
+    except Exception as exc:
+        if verifier.verify:
+            raise
+        click.secho(exc, err=True, bg="red")
+        rv = 2 if isinstance(exc, BadConfig) else 1
+
+    click.get_current_context().exit(rv)
diff --git a/server/Makefile b/server/Makefile
@@ -20,6 +20,7 @@ INSTALL = install
 INSTALLOPTS = --directory
 
 click-scripts = \
+	pbench-audit \
 	pbench-report-generator \
 	pbench-tree-manage \
 	pbench-user-create \
diff --git a/setup.cfg b/setup.cfg
@@ -24,6 +24,7 @@ where = lib
 
 [entry_points]
 console_scripts =
+   pbench-audit = pbench.cli.server.audit:audit
    pbench-cleanup = pbench.cli.agent.commands.cleanup:main
    pbench-clear-results = pbench.cli.agent.commands.results.clear:main
    pbench-clear-tools = pbench.cli.agent.commands.tools.clear:main
