Http metrics and exporters

Makefile

@@ -31,7 +31,7 @@ stop:
 REGISTRY ?= localhost:5000
 WORKERS  ?= 2
 ENV_FILE ?= .env
-SWARM_VARS = REGISTRY CERTBOT_DOMAIN CERTBOT_EMAIL NFS_SERVER_IP NFS_BASE_PATH WORKER_CPU_LIMIT WORKER_MEMORY_LIMIT WORKER_CPU_RESERVATION WORKER_MEMORY_RESERVATION
+SWARM_VARS = REGISTRY CERTBOT_DOMAIN CERTBOT_EMAIL NFS_SERVER_IP TEXTFILE_DIR NFS_BASE_PATH WORKER_CPU_LIMIT WORKER_MEMORY_LIMIT WORKER_CPU_RESERVATION WORKER_MEMORY_RESERVATION
 SWARM_ENV = ENV_FILE="$(ENV_FILE)" $(foreach v,$(SWARM_VARS),$(v)="$(shell grep '^$(v)=' $(ENV_FILE) | head -1 | cut -d= -f2-)")
 
 start-swarm:

backend/apps/ifc_validation/tasks/check_programs.py

@@ -89,6 +89,12 @@ def run_subprocess_wait(*popen_args, check=False, **popen_kwargs):
         raise
     retcode = process.returncode
     stdout, stderr = "".join(out_chunks), "".join(err_chunks)
+    if retcode is not None and retcode < 0:
+        # killed by a signal; -9 (SIGKILL) usually means the container hit its
+        # memory limit and the kernel OOM-killed this subprocess. Without this
+        # line such deaths are indistinguishable from ordinary failures.
+        logger.warning(f"Subprocess was killed by signal {-retcode} (likely OOM if 9); "
+                       f"peak RSS before death: {peak_rss_kb} kB")
     if check and retcode != 0:
         raise subprocess.CalledProcessError(retcode, popen_args[0], output=stdout, stderr=stderr)
     return proc_output(retcode, stdout, stderr, popen_args[0] if popen_args else [], peak_rss_kb, min_mem_available_kb)

backend/core/settings.py

@@ -67,6 +67,7 @@
     "drf_spectacular",                   # OpenAPI/Swagger
     "drf_spectacular_sidecar",           # required for Django collectstatic discovery
     "explorer",                          # Django SQL Explorer
+    "django_prometheus",                 # HTTP metrics for Prometheus (/metrics, internal only)
 
     "django_celery_results",             # Celery result backend
     "django_celery_beat",                # Celery scheduled tasks
@@ -88,6 +89,8 @@
 )
 
 MIDDLEWARE = [
+    # must be FIRST so the request timer starts before all other middleware
+    "django_prometheus.middleware.PrometheusBeforeMiddleware",
     #"django.middleware.gzip.GZipMiddleware",  # WE DO THIS IN NGINX
     "django.middleware.security.SecurityMiddleware",
     "django.contrib.sessions.middleware.SessionMiddleware",
@@ -97,6 +100,8 @@
     "django.contrib.auth.middleware.AuthenticationMiddleware",
     "django.contrib.messages.middleware.MessageMiddleware",
     "django.middleware.clickjacking.XFrameOptionsMiddleware",
+    # must be LAST so the response is timed after all other middleware
+    "django_prometheus.middleware.PrometheusAfterMiddleware",
 ]
 
 if DEVELOPMENT or PREVIEW:

backend/core/urls.py

@@ -45,6 +45,11 @@ def redirect_to_v1(request, resource, suffix=None):
 
 urlpatterns = [
 
+    # Prometheus scrape endpoint (/metrics). Internal only: nginx serves the React
+    # app at / and never proxies this path, so it is reachable solely on the
+    # overlay network (backend:8000).
+    path('', include('django_prometheus.urls')),
+
     # Django Admin
     path("admin/",           admin.site.urls),
 

backend/gunicorn.conf.py

@@ -0,0 +1,11 @@
+"""Gunicorn hooks for prometheus_client multiprocess mode.
+
+With multiple workers each process keeps its own counters in
+PROMETHEUS_MULTIPROC_DIR; this hook cleans up when a worker dies, otherwise
+the directory slowly fills with files of dead pids.
+"""
+from prometheus_client import multiprocess
+
+
+def child_exit(server, worker):
+    multiprocess.mark_process_dead(worker.pid)

backend/requirements.txt

@@ -47,6 +47,7 @@ python-ranges==1.2.2
 pyproj==3.7.1
 python-dateutil==2.9.0.post0
 filetype==1.2.0
+django-prometheus==2.5.0
 
 # dev
 django-debug-toolbar==6.0.0

docker-compose.swarm.nodb.yml

@@ -235,6 +235,62 @@ services:
                 condition: on-failure
                 delay: 5s
 
+    # Serves batch metrics that cron jobs on the manager write as .prom files
+    # (per-rule gherkin costs, harvested peak-RSS). Separate manager-only service:
+    # mounting the directory into the global node_exporter breaks nodes that do
+    # not have the path (reject-loop, seen on DEV 30 Jul).
+    textfile_exporter:
+        image: prom/node-exporter:v1.12.1
+        command:
+            - '--collector.disable-defaults'
+            - '--collector.textfile'
+            - '--collector.textfile.directory=/textfile'
+        volumes:
+            - ${TEXTFILE_DIR}:/textfile:ro
+        networks:
+            - validate
+        deploy:
+            replicas: 1
+            placement:
+                constraints: [node.role == manager]
+            restart_policy:
+                condition: on-failure
+                delay: 5s
+
+    # Per-container memory/CPU (cAdvisor). Closes the measuring blind spot behind
+    # the false-quarantine incident: long-lived daemons inside containers (clamd)
+    # were invisible to both host-level and per-subprocess measurements.
+    cadvisor:
+        # v0.55+: v0.52 chokes on Docker 29's containerd image store (rw-layer
+        # lookup fails -> ALL metrics for those containers silently dropped).
+        image: gcr.io/cadvisor/cadvisor:v0.55.1
+        command:
+            - '--docker_only=true'
+            - '--housekeeping_interval=15s'
+            - '--store_container_labels=false'
+            # keep only this label: needed to group metrics per swarm service
+            - '--whitelisted_container_labels=com.docker.swarm.service.name'
+            # disk/diskIO also disabled: the rw-layer lookup they require breaks
+            # on Docker 29's containerd image store (no overlayfs/layerdb path),
+            # which silently drops ALL metrics for those containers.
+            - '--disable_metrics=percpu,sched,tcp,udp,advtcp,process,hugetlb,referenced_memory,cpu_topology,resctrl,disk,diskIO'
+        volumes:
+            - /:/rootfs:ro
+            - /var/run:/var/run:ro
+            - /sys:/sys:ro
+            - /var/lib/docker/:/var/lib/docker:ro
+            - /dev/disk/:/dev/disk:ro
+        networks:
+            - validate
+        deploy:
+            mode: global
+            resources:
+                limits:
+                    memory: 512M
+            restart_policy:
+                condition: on-failure
+                delay: 5s
+
     celery_exporter:
         image: danihodovic/celery-exporter:0.12.2
         environment:

docker/backend/server-entrypoint.sh

@@ -28,4 +28,9 @@ DJANGO_GUNICORN_THREADS_PER_WORKER=${DJANGO_GUNICORN_THREADS_PER_WORKER:-4} # de
 echo "Number of worker processes: $DJANGO_GUNICORN_WORKERS"
 echo "Number of threads per worker: $DJANGO_GUNICORN_THREADS_PER_WORKER"
 
-gunicorn core.wsgi --bind 0.0.0.0:8000 --workers $DJANGO_GUNICORN_WORKERS --threads $DJANGO_GUNICORN_THREADS_PER_WORKER --worker-class gevent --worker-tmp-dir /dev/shm --timeout 60 --keep-alive 60
+# prometheus_client multiprocess mode: one shared dir for all gunicorn workers.
+# Must be wiped on boot or counters from previous runs leak into the totals.
+export PROMETHEUS_MULTIPROC_DIR=/dev/shm/prometheus_metrics
+rm -rf "$PROMETHEUS_MULTIPROC_DIR" && mkdir -p "$PROMETHEUS_MULTIPROC_DIR"
+
+gunicorn core.wsgi -c /app/backend/gunicorn.conf.py --bind 0.0.0.0:8000 --workers $DJANGO_GUNICORN_WORKERS --threads $DJANGO_GUNICORN_THREADS_PER_WORKER --worker-class gevent --worker-tmp-dir /dev/shm --timeout 60 --keep-alive 60

docker/grafana/dashboards/vs-platform-usage.json

@@ -16,11 +16,11 @@
       "targets": [
         {
           "format": "time_series",
-          "rawSql": "SELECT created::date AS time, COUNT(*)::float AS validations FROM ifc_validation_request WHERE created > NOW() - INTERVAL '30 days' GROUP BY 1 ORDER BY 1",
+          "rawSql": "SELECT created::date AS time, COUNT(*)::float AS validations FROM ifc_validation_request WHERE $__timeFilter(created) GROUP BY 1 ORDER BY 1",
           "refId": "A"
         }
       ],
-      "title": "Validation requests per day (30d)",
+      "title": "Validation requests per day",
       "type": "timeseries",
       "description": "Number of files submitted per day (fixed 30-day window, independent of the time range above). Includes requests that were soft-deleted later."
     },
@@ -39,13 +39,13 @@
       "targets": [
         {
           "format": "table",
-          "rawSql": "SELECT type, COUNT(*) AS n, ROUND(percentile_cont(0.5) WITHIN GROUP (ORDER BY EXTRACT(EPOCH FROM ended-started))::numeric,1) AS p50_s, ROUND(percentile_cont(0.95) WITHIN GROUP (ORDER BY EXTRACT(EPOCH FROM ended-started))::numeric,1) AS p95_s FROM ifc_validation_task WHERE ended IS NOT NULL AND started IS NOT NULL AND created > NOW() - INTERVAL '90 days' GROUP BY type ORDER BY p95_s DESC",
+          "rawSql": "SELECT type, COUNT(*) AS n, ROUND(percentile_cont(0.5) WITHIN GROUP (ORDER BY EXTRACT(EPOCH FROM ended-started))::numeric,1) AS p50_s, ROUND(percentile_cont(0.95) WITHIN GROUP (ORDER BY EXTRACT(EPOCH FROM ended-started))::numeric,1) AS p95_s FROM ifc_validation_task WHERE ended IS NOT NULL AND started IS NOT NULL AND $__timeFilter(created) GROUP BY type ORDER BY p95_s DESC",
           "refId": "A"
         }
       ],
-      "title": "Duration per task type: p50 / p95 (90d, seconds)",
+      "title": "Duration per task type: p50 / p95 (seconds)",
       "type": "table",
-      "description": "Median (p50) and slow-tail (p95) duration in seconds per validation step, over 90 days. From ifc_validation_task.ended - started."
+      "description": "Median (p50) and slow-tail (p95) duration in seconds per validation step, over the selected time range. From ifc_validation_task.ended - started."
     },
     {
       "datasource": {
@@ -62,11 +62,11 @@
       "targets": [
         {
           "format": "time_series",
-          "rawSql": "SELECT DATE(r.created) AS time, percentile_cont(0.95) WITHIN GROUP (ORDER BY EXTRACT(EPOCH FROM ft.fs - r.created)) AS queue_wait_p95_s FROM ifc_validation_request r JOIN LATERAL (SELECT MIN(t.started) AS fs FROM ifc_validation_task t WHERE t.request_id = r.id) ft ON ft.fs IS NOT NULL WHERE r.created > NOW() - INTERVAL '30 days' GROUP BY 1 ORDER BY 1",
+          "rawSql": "SELECT DATE(r.created) AS time, percentile_cont(0.95) WITHIN GROUP (ORDER BY EXTRACT(EPOCH FROM ft.fs - r.created)) AS queue_wait_p95_s FROM ifc_validation_request r JOIN LATERAL (SELECT MIN(t.started) AS fs FROM ifc_validation_task t WHERE t.request_id = r.id) ft ON ft.fs IS NOT NULL WHERE $__timeFilter(r.created) GROUP BY 1 ORDER BY 1",
           "refId": "A"
         }
       ],
-      "title": "Queue wait time p95 per day (s, 30d)",
+      "title": "Queue wait time p95 per day (s)",
       "type": "timeseries",
       "description": "Wait time between submission and the start of the first task. NOTE: on DEV, tasks are sometimes re-run manually on old requests, which inflates this to hours. Read it as a trend, not an absolute."
     },
@@ -92,11 +92,11 @@
       "targets": [
         {
           "format": "time_series",
-          "rawSql": "SELECT created::date AS time, ROUND(100.0 * SUM((status='FAILED')::int) / COUNT(*), 1) AS failure_rate FROM ifc_validation_request WHERE created > NOW() - INTERVAL '30 days' GROUP BY 1 ORDER BY 1",
+          "rawSql": "SELECT created::date AS time, ROUND(100.0 * SUM((status='FAILED')::int) / COUNT(*), 1) AS failure_rate FROM ifc_validation_request WHERE $__timeFilter(created) GROUP BY 1 ORDER BY 1",
           "refId": "A"
         }
       ],
-      "title": "Failure rate per day (%, 30d)",
+      "title": "Failure rate per day (%)",
       "type": "timeseries",
       "description": "Percentage of requests per day that ended in status FAILED."
     },
@@ -115,13 +115,13 @@
       "targets": [
         {
           "format": "table",
-          "rawSql": "SELECT EXTRACT(HOUR FROM created)::int AS hour, COUNT(*) AS requests FROM ifc_validation_request WHERE created > NOW() - INTERVAL '90 days' GROUP BY 1 ORDER BY 1",
+          "rawSql": "SELECT EXTRACT(HOUR FROM created)::int AS hour, COUNT(*) AS requests FROM ifc_validation_request WHERE $__timeFilter(created) GROUP BY 1 ORDER BY 1",
           "refId": "A"
         }
       ],
-      "title": "Activity by hour of day (90d)",
+      "title": "Activity by hour of day",
       "type": "barchart",
-      "description": "Which hour of the day the platform is used (UTC), over 90 days."
+      "description": "Which hour of the day the platform is used (UTC), over the selected time range."
     },
     {
       "datasource": {
@@ -162,7 +162,7 @@
       ],
       "title": "Stuck requests (>1h, not finished)",
       "type": "stat",
-      "description": "Requests older than one hour that are still not finished (not COMPLETED/FAILED). Should be 0."
+      "description": "Requests older than one hour that are still not finished (not COMPLETED/FAILED). Should be 0. Deliberately ignores the dashboard time range: it shows the current state."
     },
     {
       "datasource": {
@@ -179,13 +179,13 @@
       "targets": [
         {
           "format": "table",
-          "rawSql": "SELECT file_name, ROUND(size/1024.0/1024.0,1) AS mb, status, EXTRACT(EPOCH FROM completed-created)::int AS duration_s, created FROM ifc_validation_request WHERE created > NOW() - INTERVAL '30 days' ORDER BY size DESC NULLS LAST LIMIT 10",
+          "rawSql": "SELECT file_name, ROUND(size/1024.0/1024.0,1) AS mb, status, EXTRACT(EPOCH FROM completed-created)::int AS duration_s, created FROM ifc_validation_request WHERE $__timeFilter(created) ORDER BY size DESC NULLS LAST LIMIT 10",
           "refId": "A"
         }
       ],
-      "title": "Largest files in the last 30d (top 10)",
+      "title": "Largest files (top 10)",
       "type": "table",
-      "description": "The ten largest files of the last 30 days. Odd-looking file names are non-Latin names exactly as stored in the database."
+      "description": "The ten largest files in the selected time range. Odd-looking file names are non-Latin names exactly as stored in the database."
     },
     {
       "id": 8,
@@ -216,14 +216,14 @@
         {
           "refId": "A",
           "format": "time_series",
-          "rawSql": "SELECT created::date AS time, channel, COUNT(*)::float AS uploads FROM ifc_validation_request WHERE created > NOW() - INTERVAL '90 days' AND channel IS NOT NULL GROUP BY 1,2 ORDER BY 1"
+          "rawSql": "SELECT created::date AS time, channel, COUNT(*)::float AS uploads FROM ifc_validation_request WHERE $__timeFilter(created) AND channel IS NOT NULL GROUP BY 1,2 ORDER BY 1"
         }
       ]
     },
     {
       "id": 9,
       "type": "table",
-      "title": "Top API users (90d)",
+      "title": "Top API users",
       "description": "Per account: number of uploads, total and average size. Some accounts have no email filled in, hence grouping by username.",
       "gridPos": {
         "h": 8,
@@ -239,7 +239,7 @@
         {
           "refId": "A",
           "format": "table",
-          "rawSql": "SELECT u.username, COUNT(*) AS uploads, ROUND(SUM(r.size)/1024.0/1024.0,1) AS total_mb, ROUND(AVG(r.size)/1024.0/1024.0,2) AS avg_mb, MAX(r.created)::date AS last_upload FROM ifc_validation_request r JOIN auth_user u ON u.id = r.created_by_id WHERE r.channel='API' AND r.created > NOW() - INTERVAL '90 days' GROUP BY 1 ORDER BY uploads DESC LIMIT 15"
+          "rawSql": "SELECT u.username, COUNT(*) AS uploads, ROUND(SUM(r.size)/1024.0/1024.0,1) AS total_mb, ROUND(AVG(r.size)/1024.0/1024.0,2) AS avg_mb, MAX(r.created)::date AS last_upload FROM ifc_validation_request r JOIN auth_user u ON u.id = r.created_by_id WHERE r.channel='API' AND $__timeFilter(r.created) GROUP BY 1 ORDER BY uploads DESC LIMIT 15"
         }
       ]
     },
@@ -262,9 +262,90 @@
         {
           "refId": "A",
           "format": "table",
-          "rawSql": "SELECT CASE WHEN status_reason LIKE '%duplicate key%' THEN 'duplicate key (race on concurrent requests)' WHEN status_reason LIKE '%NUL (0x00)%' THEN 'NUL bytes in text (PostgreSQL rejects)' WHEN status_reason LIKE '%TaskContext%' THEN 'code bug: TaskContext missing proc' WHEN status_reason LIKE '%NoneType%' THEN 'code bug: NoneType has no id' WHEN status_reason IS NULL OR status_reason='' THEN '(no reason recorded)' ELSE split_part(status_reason, E'\\n', 1) END AS cause, COUNT(*) AS count, COUNT(DISTINCT type) AS task_types, MAX(created)::date AS last_seen FROM ifc_validation_task WHERE status='FAILED' GROUP BY 1 ORDER BY aantal DESC LIMIT 15"
+          "rawSql": "SELECT CASE WHEN status_reason LIKE '%duplicate key%' THEN 'duplicate key (race on concurrent requests)' WHEN status_reason LIKE '%NUL (0x00)%' THEN 'NUL bytes in text (PostgreSQL rejects)' WHEN status_reason LIKE '%TaskContext%' THEN 'code bug: TaskContext missing proc' WHEN status_reason LIKE '%NoneType%' THEN 'code bug: NoneType has no id' WHEN status_reason IS NULL OR status_reason='' THEN '(no reason recorded)' ELSE split_part(status_reason, E'\\n', 1) END AS cause, COUNT(*) AS count, COUNT(DISTINCT type) AS task_types, MAX(created)::date AS last_seen FROM ifc_validation_task WHERE status='FAILED' AND $__timeFilter(created) GROUP BY 1 ORDER BY 2 DESC LIMIT 15"
         }
       ]
+    },
+    {
+      "datasource": {
+        "type": "grafana-postgresql-datasource",
+        "uid": "devpg"
+      },
+      "gridPos": {
+        "h": 8,
+        "w": 12,
+        "x": 0,
+        "y": 39
+      },
+      "id": 11,
+      "targets": [
+        {
+          "refId": "A",
+          "format": "time_series",
+          "rawSql": "SELECT date_trunc('week', created) AS \"time\", COUNT(*) AS \"uploads\", COUNT(DISTINCT created_by_id) AS \"unique users\" FROM ifc_validation_request WHERE channel='API' AND $__timeFilter(created) GROUP BY 1 ORDER BY 1",
+          "datasource": {
+            "type": "grafana-postgresql-datasource",
+            "uid": "devpg"
+          }
+        }
+      ],
+      "title": "API uploads per week",
+      "type": "timeseries",
+      "description": "Weekly API-channel uploads and unique API users. Context: the external API user programme runs on DEV; on PROD this shows only internal usage until the API is opened up. Channel field is only reliable after Jul 2025 (migration wrote everything before that as WEBUI)."
+    },
+    {
+      "datasource": {
+        "type": "prometheus",
+        "uid": "prometheus"
+      },
+      "gridPos": {
+        "h": 8,
+        "w": 6,
+        "x": 12,
+        "y": 39
+      },
+      "id": 12,
+      "targets": [
+        {
+          "refId": "A",
+          "expr": "sum by (status) (rate(django_http_responses_total_by_status_total[5m]))",
+          "legendFormat": "{{status}}",
+          "datasource": {
+            "type": "prometheus",
+            "uid": "prometheus"
+          }
+        }
+      ],
+      "title": "HTTP responses by status (incl. 429)",
+      "type": "timeseries",
+      "description": "HTTP responses per status code straight from Django - including 429 rate-limit rejections, which never reach the database and were invisible until now."
+    },
+    {
+      "datasource": {
+        "type": "prometheus",
+        "uid": "prometheus"
+      },
+      "gridPos": {
+        "h": 8,
+        "w": 6,
+        "x": 18,
+        "y": 39
+      },
+      "id": 13,
+      "targets": [
+        {
+          "refId": "A",
+          "expr": "histogram_quantile(0.95, sum by (le) (rate(django_http_requests_latency_seconds_by_view_method_bucket[5m])))",
+          "legendFormat": "p95",
+          "datasource": {
+            "type": "prometheus",
+            "uid": "prometheus"
+          }
+        }
+      ],
+      "title": "HTTP p95 latency (django)",
+      "type": "timeseries",
+      "description": "95th percentile response time of the Django backend, measured inside the app."
     }
   ],
   "refresh": "5m",
@@ -282,4 +363,4 @@
   "schemaVersion": 39,
   "editable": true,
   "timezone": "browser"
-}
+}