stats: rework summary statistics collection and display

The front page graph of "Builds per Day" is too minimal for any
meaningful use.  Let's rework it to show per-day numbers for:

- total build requests
- total failures
- count of requests satisfied by already-built images

Many internal enhancements were made and some bugs were fixed.

- Centralize the mechanism for logging summary build events.
- The old cache-hits value was completely incorrect, being logged
  for every download and hence was grossly over reporting.
- Rework the aggregation bucket boundaries to land on midnight,
  so that the "per day" values really are per day.
- Add lines to graph as mentioned above.
- Add a test for the 'builds-per-day' API call.
- Extend the summary stats test to verify all data.

Since the old summary data format is no longer used, a conversion
script is provided with this commit.  See misc/stats_modernize.py,
which is intended to be run once before this upgraded code is
deployed (although it is safe to run multiple times, its only
destructive act is to delete the invalid 'cache-hits').

Link: #1513
Signed-off-by: Eric Fahlgren <ericfahlgren@gmail.com>

Author: efahl

asu/build.py

@@ -15,6 +15,7 @@
 from asu.package_changes import apply_package_changes
 from asu.util import (
     add_timestamp,
+    add_build_event,
     check_manifest,
     diff_packages,
     fingerprint_pubkey_usign,
@@ -32,7 +33,7 @@
 log = logging.getLogger("rq.worker")
 
 
-def build(build_request: BuildRequest, job=None):
+def _build(build_request: BuildRequest, job=None):
     """Build image request and setup ImageBuilders automatically
 
     The `request` dict contains properties of the requested image.
@@ -429,3 +430,15 @@ def build(build_request: BuildRequest, job=None):
     job.save_meta()
 
     return json_content
+
+
+def build(build_request: BuildRequest, job=None):
+    try:
+        result = _build(build_request, job)
+    except Exception:
+        # Log all build errors, including internal server errors.
+        add_build_event("failures")
+        raise
+    else:
+        add_build_event("successes")
+        return result

asu/routers/api.py

@@ -10,6 +10,7 @@
 from asu.config import settings
 from asu.util import (
     add_timestamp,
+    add_build_event,
     client_get,
     get_branch,
     get_queue,
@@ -194,9 +195,6 @@ def api_v1_build_get(request: Request, request_hash: str, response: Response) ->
             "detail": "could not find provided request hash",
         }
 
-    if job.is_finished and request.method != "HEAD":
-        add_timestamp("stats:cache-hits", {"stats": "cache-hits"})
-
     content, status, headers = return_job_v1(job)
     response.headers.update(headers)
     response.status_code = status
@@ -214,6 +212,8 @@ def api_v1_build_post(
     # Sanitize the profile in case the client did not (bug in older LuCI app).
     build_request.profile = build_request.profile.replace(",", "_")
 
+    add_build_event("requests")
+
     request_hash: str = get_request_hash(build_request)
     job: Job = get_queue().fetch_job(request_hash)
     status: int = 200
@@ -235,7 +235,7 @@ def api_v1_build_post(
     )
 
     if job is None:
-        add_timestamp("stats:cache-misses", {"stats": "cache-misses"})
+        add_build_event("cache-misses")
 
         content, status = validate_request(request.app, build_request)
         if content:
@@ -261,7 +261,7 @@ def api_v1_build_post(
         )
     else:
         if job.is_finished:
-            add_timestamp("stats:cache-hits", {"stats": "cache-hits"})
+            add_build_event("cache-hits")
 
     content, status, headers = return_job_v1(job)
     response.headers.update(headers)

asu/routers/stats.py

@@ -1,47 +1,60 @@
-from datetime import datetime
+from datetime import datetime as dt, timedelta, UTC
 
 from fastapi import APIRouter
 
-from asu.util import get_redis_client
+from asu.util import get_redis_ts
 
 router = APIRouter()
 
 
-def get_redis_ts():
-    return get_redis_client().ts()
+DAY_MS = 24 * 60 * 60 * 1000
+N_DAYS = 30
 
 
 @router.get("/builds-per-day")
-def get_builds_per_day():
-    ts = get_redis_ts()
-    now = int(datetime.utcnow().timestamp() * 1000)
-    start = now - 30 * 24 * 60 * 60 * 1000  # last 30 days
+def get_builds_per_day() -> dict:
+    """
+    References:
+    https://redis.readthedocs.io/en/latest/redismodules.html#redis.commands.timeseries.commands.TimeSeriesCommands.range
+    https://www.chartjs.org/docs/latest/charts/line.html
+    """
+
+    # "stop" is next midnight to define buckets on exact day boundaries.
+    stop = dt.now(UTC).replace(hour=0, minute=0, second=0, microsecond=0)
+    stop += timedelta(days=1)
+    stop = int(stop.timestamp() * 1000)
+    start = stop - N_DAYS * DAY_MS
+
+    stamps = list(range(start, stop, DAY_MS))
+    labels = [str(dt.fromtimestamp(stamp // 1000, UTC))[:10] + "Z" for stamp in stamps]
 
-    # aggregate all time series labeled with stats=builds
-    results = ts.mrange(
+    ts = get_redis_ts()
+    rc = ts.client
+    range_options = dict(
         from_time=start,
-        to_time=now,
-        filters=["stats=builds"],
-        with_labels=False,
+        to_time=stop,
+        align=start,  # Ensures alignment of X values with "stamps".
         aggregation_type="sum",
-        bucket_size_msec=86400000,  # 1 day (24 hours)
+        bucket_size_msec=DAY_MS,
     )
 
-    # create a map from timestamp to build count
-    daily_counts = {}
-
-    for entry in results:
-        data = list(entry.values())[0][1]
-        for ts, value in data:
-            daily_counts[ts] = daily_counts.get(ts, 0) + int(value)
-
-    # sort by timestamp
-    sorted_data = sorted(daily_counts.items())
-
-    labels = [datetime.utcfromtimestamp(ts / 1000).isoformat() for ts, _ in sorted_data]
-    values = [count for _, count in sorted_data]
+    def get_dataset(event: str, color: str) -> dict:
+        """Fills "data" array completely, supplying 0 for missing values."""
+        key = f"stats:build:{event}"
+        result = ts.range(key, **range_options) if rc.exists(key) else []
+        data_map = dict(result)
+        return {
+            "label": event.title(),
+            "data": [data_map.get(stamp, 0) for stamp in stamps],
+            "color": color,
+        }
 
     return {
         "labels": labels,
-        "datasets": [{"label": "Builds per day", "data": values}],
+        "datasets": [
+            # See add_build_event for valid "event" values.
+            get_dataset("requests", "green"),
+            get_dataset("cache-hits", "orange"),
+            get_dataset("failures", "red"),
+        ],
     }

asu/templates/overview.html

@@ -116,24 +116,22 @@ <h2>Builds per Day (last 30 days)</h2>
                         labels: data.labels,
                         datasets: data.datasets.map(ds => ({
                             data: ds.data,
+                            label: ds.label,
+                            backgroundColor: ds.color,
+                            borderColor: ds.color,
+                            borderJoinStyle: "round",
                             fill: false
                         }))
                     },
                     options: {
                         responsive: true,
                         scales: {
-                          x: {
-                            display: false
-                          },
-                          y: {
-                            display: true
-                          }
+                            x: { display: false },
+                            y: { display: true }
                         },
                         plugins: {
-                          legend: {
-                            display: false
-                          },
-                            title: { display: false }
+                            legend: { display: true },
+                            title:  { display: false }
                         }
                     }
                 });

asu/util.py

@@ -32,6 +32,10 @@ def get_redis_client(unicode: bool = True) -> redis.client.Redis:
     return redis.from_url(settings.redis_url, decode_responses=unicode)
 
 
+def get_redis_ts():
+    return get_redis_client().ts()
+
+
 def client_get(url: str, ttl: int = 3600) -> Response:
     return hishel.CacheClient(
         storage=hishel.RedisStorage(client=get_redis_client(False), ttl=ttl),
@@ -43,7 +47,7 @@ def add_timestamp(key: str, labels: dict[str, str] = {}, value: int = 1) -> None
     if not settings.server_stats:
         return
     log.debug(f"Adding timestamp to {key}: {labels}")
-    get_redis_client().ts().add(
+    get_redis_ts().add(
         key,
         value=value,
         timestamp="*",
@@ -52,6 +56,29 @@ def add_timestamp(key: str, labels: dict[str, str] = {}, value: int = 1) -> None
     )
 
 
+def add_build_event(event: str) -> None:
+    """
+    Logs summary statistics for build events:
+
+    - requests     - total number of calls to /build API, logged for all build
+                     requests, irrespective of validity, success or failure
+    - cache-hits   - count of build requests satisfied by already-existing builds
+    - cache-misses - count of build requests sent to builder
+    - successes    - count of builder runs with successful completion
+    - failures     - count of builder runs that failed
+
+    Note that for validation, you can check that:
+    - cache-misses = successes + failures
+    - requests = cache-hits + cache-misses
+
+    The summary stats key prefix is 'stats:build:*'.
+    """
+    assert event in {"requests", "cache-hits", "cache-misses", "successes", "failures"}
+
+    key: str = f"stats:build:{event}"
+    add_timestamp(key, {"stats": "summary"})
+
+
 def get_queue() -> Queue:
     """Return the current queue
 

misc/stats_modernize.py

@@ -0,0 +1,47 @@
+from asu.util import get_redis_ts
+
+stat_types = (
+    "cache-hits",
+    "cache-misses",
+    "failures",
+    "requests",
+    "successes",
+)
+
+ts = get_redis_ts()
+rc = ts.client
+
+converted = rc.exists("stats:build:requests")
+force = False
+if converted and not force:
+    print("Already converted =====================")
+else:
+    print("Converting ============================")
+
+    if rc.exists("stats:cache-misses"):
+        # Note: "rename" overwrites any existing destination...
+        rc.rename("stats:cache-misses", "stats:build:cache-misses")
+    if rc.exists("stats:cache-hits"):
+        # Old stats are completely incorrect, so just delete them.
+        rc.delete("stats:cache-hits")
+
+    for stat_type in stat_types:
+        key = f"stats:build:{stat_type}"
+        func = ts.alter if rc.exists(key) else ts.create
+        func(key, labels={"stats": "summary"}, duplicate_policy="sum")
+
+    # Attempt to repopulate total requests and success values as
+    # accurately as possible using existing stats:builds:* data.
+    ts.delete("stats:build:requests", "-", "+")  # Empty them out.
+    ts.delete("stats:build:successes", "-", "+")
+    all_builds = ts.mrange("-", "+", filters=["stats=builds"])
+    for build in all_builds:
+        _, data = build.popitem()
+        series = data[1]
+        for stamp, value in series:
+            ts.add("stats:build:requests", timestamp=stamp, value=value)
+            ts.add("stats:build:successes", timestamp=stamp, value=value)
+
+    for stat_type in stat_types:
+        key = f"stats:build:{stat_type}"
+        print(f"{key:<25} - {ts.info(key).total_samples} samples")

tests/test_api.py

@@ -157,6 +157,14 @@ def save_meta(self):
     try:
         build(build_request, fake_job())
     except Exception as exc:
+        chain = exc
+        while hasattr(chain, "__context__") and chain.__context__:
+            # We want the original exception, not anything that FakeRedis
+            # generated during processing of it.
+            chain = chain.__context__
+            if isinstance(chain, RuntimeError):
+                exc = chain
+                break
         assert str(exc).startswith(
             "Image not found: ghcr.io/openwrt/imagebuilder:lantiq-xrx200-v24.10.1"
         )