ipx/grafana/dashboard.py

"""The iPX dashboard in Grafana, from Loki (the containers' logs, shipped by Alloy) and Tempo:
ipx, and since #210 ipx-web and ipx-directory.

    python3 grafana/dashboard.py > /mnt/fast/arcane/projects/monitoring/grafana-provisioning/dashboards/ipx.json

Grafana reads that file on its own within a minute; edits made in Grafana are refused. The
Daemon row reads ipx's /metrics from Prometheus (job ipx, #194); the rest read the fields of
ipx's JSON log (IPX_LOG_FORMAT=json): renaming a field in web.rs access_log or ipc.rs log_event
has to be matched here. `dashboard.py queries` prints each
query, to try against Loki.
"""
import json, sys

LOKI = {"type": "loki", "uid": "${loki}"}
TEMPO = {"type": "tempo", "uid": "${tempo}"}
PROM = {"type": "prometheus", "uid": "${prometheus}"}
SEL = '{container="iPX"}'
# ipx logs one JSON object a line (IPX_LOG_FORMAT=json). Each scan and download event carries its
# fields (ev, feed, new, bytes, msg, error.type, ...); each request its method, path, route, status
# and duration_ms. Events are logged under ipx::scan, the healthcheck's status under ipx::io, so
# the filter is on the ev field, not the target.
EV = SEL + ' |= "\\"ev\\":\\"" | json | __error__="" | ev != ""'
HTTP = SEL + ' |= "\\"target\\":\\"ipx::http\\"" | json | __error__="" | path != "/api/events"'
BAD = SEL + ' | json | __error__="" | level =~ "WARN|ERROR"'
TEXT = ' | line_format "{{.level}} {{.target}}: {{.message}}"'
TRACES = '{resource.service.name="ipx" && resource.deployment.environment.name="production"'
# The directory's JSON log (#204): a line a request (method, path, status, duration_ms, token), a
# line a snapshot (instance, accepted, refused_*), a line a refresher round (checked) and one a
# failed feed check (feed, error).
DIR = '{container="ipx-directory"} | json | __error__=""'
DIR_HTTP = '{container="ipx-directory"} |= "ipx_directory::http" | json | __error__=""'
# ipx-web's Caddy access log (#203, #210): request.uri, status, duration in seconds. The page and
# its files only: /api and /media are ipx's, and in its own log already.
WEB = ('{container="ipx-web"} |= "http.log.access" | json | __error__=""'
       ' | request_uri !~ "/(api|media)/.*"')
OTHERS_BAD = '{container=~"ipx-web|ipx-directory"} | json | __error__="" | level =~ "(?i)warn|error"'


def status(field):
    return f'max(max_over_time({EV} | ev = "status" | unwrap {field} [10m]))'


QUERIES = {}
panels, y = [], 0
pid = 0


def panel(kind, title, w, h, x, targets, **extra):
    global pid
    pid += 1
    p = {"id": pid, "type": kind, "title": title, "gridPos": {"x": x, "y": y, "w": w, "h": h},
         "datasource": targets[0].get("datasource", LOKI), "targets": targets}
    p.update(extra)
    panels.append(p)
    return p


def loki(expr, ref="A", legend=None, instant=False, kind=None):
    QUERIES[expr] = instant
    t = {"refId": ref, "datasource": LOKI, "expr": expr, "queryType": "instant" if instant else "range"}
    if legend:
        t["legendFormat"] = legend
    return t


def prom(expr, ref="A", legend=None):
    # ipx's /metrics (#194), scraped by Prometheus as job ipx.
    t = {"refId": ref, "datasource": PROM, "expr": expr}
    if legend:
        t["legendFormat"] = legend
    return t


def row(title):
    global y, pid
    pid += 1
    panels.append({"id": pid, "type": "row", "title": title, "collapsed": False,
                   "gridPos": {"x": 0, "y": y, "w": 24, "h": 1}, "panels": []})
    y += 1


def stat(title, expr, x, unit="short", color="blue", thresholds=None, desc=None):
    steps = thresholds or [{"color": color, "value": None}]
    return panel("stat", title, 4, 4, x, [loki(expr, instant=True)], description=desc or "",
                 fieldConfig={"defaults": {"unit": unit, "color": {"mode": "thresholds"},
                                           "thresholds": {"mode": "absolute", "steps": steps}}, "overrides": []},
                 options={"reduceOptions": {"calcs": ["lastNotNull"], "fields": "", "values": False},
                          "colorMode": "value", "graphMode": "none", "textMode": "value"})


def ts(title, targets, x, w=12, h=8, unit="short", bars=False, stack=False, desc=""):
    custom = {"drawStyle": "bars" if bars else "line", "fillOpacity": 60 if bars else 10,
              "lineWidth": 1, "showPoints": "never", "stacking": {"mode": "normal" if stack else "none"}}
    return panel("timeseries", title, w, h, x, targets, description=desc,
                 fieldConfig={"defaults": {"unit": unit, "custom": custom}, "overrides": []},
                 options={"legend": {"displayMode": "list", "placement": "bottom"},
                          "tooltip": {"mode": "multi", "sort": "desc"}})


def table(title, targets, x, w=12, h=8, rename=None, sort=None, desc=""):
    return panel("table", title, w, h, x, targets, description=desc,
                 transformations=[{"id": "labelsToFields", "options": {"mode": "columns"}},
                                  {"id": "organize", "options": {
                                      "excludeByName": {"Time": True, "container": True, "compose_project": True,
                                                        "service_name": True},
                                      "renameByName": rename or {}}}],
                 options={"showHeader": True, "sortBy": sort or []},
                 fieldConfig={"defaults": {}, "overrides": []})


# ---- Now
row("Now")
stat("Feeds", status("feeds"), 0, desc="From the healthcheck's status answer, every 30 seconds.")
stat("Waiting to download", status("pending"), 4)
stat("Downloaded", status("downloaded"), 8, color="green")
stat("Feed failures", f'sum(count_over_time({EV} | ev="feed_error" [$__range])) or vector(0)', 12,
     thresholds=[{"color": "green", "value": None}, {"color": "orange", "value": 1}],
     desc="Failed feed checks in the time range.")
stat("Download failures", f'sum(count_over_time({EV} | ev="download_error" [$__range])) or vector(0)', 16,
     thresholds=[{"color": "green", "value": None}, {"color": "orange", "value": 1}])
stat("Warnings and errors", f'sum(count_over_time({BAD} [$__range])) or vector(0)', 20,
     thresholds=[{"color": "green", "value": None}, {"color": "orange", "value": 1}, {"color": "red", "value": 50}])
y += 4

# ---- Scans
row("Scans and downloads")
ts("New items found", [loki(f'sum(sum_over_time({EV} | ev="feed_done" | unwrap new [$__interval]))', legend="new items")],
   0, bars=True)
ts("Downloads", [loki(f'sum(count_over_time({EV} | ev="download_done" [$__interval]))', legend="saved"),
                 loki(f'sum(count_over_time({EV} | ev="download_error" [$__interval]))', ref="B", legend="failed")],
   12, bars=True)
y += 8
ts("Bytes downloaded", [loki(f'sum(sum_over_time({EV} | ev="download_done" | unwrap bytes [$__interval]))', legend="bytes")],
   0, unit="bytes", bars=True)
ts("Feeds checked per scan", [loki(f'sum(sum_over_time({EV} | ev="scan_done" | unwrap feeds [$__interval]))', legend="feeds checked")],
   12, bars=True, desc="Feeds that were due and fetched; the rest were skipped as not due.")
y += 8
table("Failing feeds", [loki(f'sum by (feed, msg) (count_over_time({EV} | ev="feed_error" [$__range]))', instant=True)],
      0, rename={"feed": "Feed", "msg": "Error", "Value": "Failures"}, sort=[{"displayName": "Failures", "desc": True}])
table("Failed downloads", [loki(f'sum by (feed, msg) (count_over_time({EV} | ev="download_error" [$__range]))', instant=True)],
      12, rename={"feed": "Feed", "msg": "Error", "Value": "Failures"}, sort=[{"displayName": "Failures", "desc": True}])
y += 8

# ---- Web
row("Web")
ts("Requests by status", [loki(f'sum by (status) (count_over_time({HTTP} [$__interval]))', legend="{{status}}")],
   0, bars=True, stack=True, desc="The event stream the page keeps open is left out.")
ts("Response time", [loki(f'quantile_over_time(0.5, {HTTP} | unwrap duration_ms [$__interval]) by ()', legend="median"),
                     loki(f'quantile_over_time(0.95, {HTTP} | unwrap duration_ms [$__interval]) by ()', ref="B", legend="95th percentile"),
                     loki(f'max_over_time({HTTP} | unwrap duration_ms [$__interval]) by ()', ref="C", legend="slowest")],
   12, unit="ms")
y += 8
table("Slowest routes", [loki(f'topk(15, avg_over_time({HTTP} | route != "" | unwrap duration_ms [$__range]) by (method, route))', instant=True)],
      0, rename={"method": "Method", "route": "Route", "Value": "Average ms"}, sort=[{"displayName": "Average ms", "desc": True}])
table("Busiest routes", [loki(f'topk(15, sum by (method, route) (count_over_time({HTTP} | route != "" [$__range])))', instant=True)],
      12, rename={"method": "Method", "route": "Route", "Value": "Requests"}, sort=[{"displayName": "Requests", "desc": True}])
y += 8

# ---- Page, from ipx-web's log
row("Page")
ts("Page and file requests by status", [loki(f'sum by (status) (count_over_time({WEB} [$__interval]))', legend="{{status}}")],
   0, bars=True, stack=True, desc="What Caddy served itself: the app, the admin and sign-in pages, scripts, styles, icons. "
                                  "A page answered 401 or 403 is ipx refusing it in /api/page-check.")
ts("Page response time", [loki(f'quantile_over_time(0.95, {WEB} | unwrap duration [$__interval]) by ()', legend="95th percentile"),
                          loki(f'max_over_time({WEB} | unwrap duration [$__interval]) by ()', ref="B", legend="slowest")],
   12, unit="s", desc="A page waits on ipx's /api/page-check before it is sent.")
y += 8

# ---- Directory, from ipx-directory's log
row("Directory")
stat("Feeds shared", 'sum(max by (instance) (max_over_time(' + DIR + ' | message="snapshot" | unwrap accepted [6h])))', 0,
     desc="The feeds each server's latest snapshot gave, added up: the same feed from two servers counts twice.")
stat("Snapshots", f'sum(count_over_time({DIR} | message="snapshot" [$__range])) or vector(0)', 4,
     desc="ipx sends one when what it shares changes, and every half hour (#211).")
stat("Refused as private", f'sum(sum_over_time({DIR} | message="snapshot" | unwrap refused_private [$__range])) or vector(0)', 8,
     thresholds=[{"color": "green", "value": None}, {"color": "red", "value": 1}],
     desc="Feeds a server sent that the directory caught as private. Not 0 means a server's own check missed one.")
stat("Feed checks", f'sum(sum_over_time({DIR} | message="feeds checked" | unwrap checked [$__range])) or vector(0)', 12)
stat("Failed feed checks", f'sum(count_over_time({DIR} | message="feed check failed" [$__range])) or vector(0)', 16,
     thresholds=[{"color": "green", "value": None}, {"color": "orange", "value": 1}],
     desc="Mostly the publishers': a feed gone or moved.")
stat("Requests refused", f'sum(count_over_time({DIR_HTTP} | status =~ "401|403" [$__range])) or vector(0)', 20,
     thresholds=[{"color": "green", "value": None}, {"color": "orange", "value": 100}],
     desc="Without a token, or with one that has not the access asked for. Now and then is someone trying a public address.")
y += 4
ts("Directory requests", [loki(f'sum by (status, token) (count_over_time({DIR_HTTP} [$__interval]))', legend="{{status}} {{token}}")],
   0, bars=True, stack=True)
ts("Feed checks", [loki(f'sum(sum_over_time({DIR} | message="feeds checked" | unwrap checked [$__interval]))', legend="checked"),
                   loki(f'sum(count_over_time({DIR} | message="feed check failed" [$__interval]))', ref="B", legend="failed")],
   12, bars=True, desc="Each feed every six hours, 25 at a time; a burst follows a snapshot with new feeds.")
y += 8
table("Directory: failing feeds", [loki(f'sum by (feed, error) (count_over_time({DIR} | message="feed check failed" [$__range]))', instant=True)],
      0, rename={"feed": "Feed id", "error": "Error", "Value": "Failures"}, sort=[{"displayName": "Failures", "desc": True}])
table("Snapshots by server", [loki(f'sum by (instance) (count_over_time({DIR} | message="snapshot" [$__range]))', instant=True)],
      12, rename={"instance": "Token", "Value": "Snapshots"}, sort=[{"displayName": "Snapshots", "desc": True}])
y += 8

# ---- Daemon, from Prometheus: what the daemon holds between requests (#194)
row("Daemon")
# Open connections stay open, idle, for ten minutes after a burst, so open at the max is not
# pressure; drawn as a line of its own it read as the pool maxing out (#199).
ts("Database connections", [prom('max(max_over_time(ipx_db_connections{job="ipx", state="in_use"}[$__interval]))', legend="in use"),
                            prom('sum(ipx_db_connections{job="ipx"})', ref="B", legend="open"),
                            prom('max(ipx_db_connections_max{job="ipx"})', ref="C", legend="most the pool opens")],
   0, w=8, desc="In use reaching the most the pool opens means requests and scans are waiting for a connection. "
                "Open connections stay open, idle, for ten minutes after a burst.")["fieldConfig"]["overrides"] = [
    {"matcher": {"id": "byName", "options": "open"},
     "properties": [{"id": "custom.lineStyle", "value": {"fill": "dash", "dash": [4, 4]}},
                    {"id": "custom.fillOpacity", "value": 0}, {"id": "color", "value": {"mode": "fixed", "fixedColor": "#8e8e8e"}}]}]
ts("Waiting", [prom('ipx_worker_queue{job="ipx"}', legend="commands for the worker"),
               prom('ipx_runtime_queue{job="ipx"}', ref="B", legend="tasks for a thread"),
               prom('ipx_downloads_pending{job="ipx"}', ref="C", legend="downloads")],
   8, w=8, desc="Scans and downloads run one at a time; a queue that only grows means the worker is stuck.")
ts("Listeners and tasks", [prom('ipx_event_listeners{job="ipx"}', legend="live-update listeners"),
                           prom('ipx_runtime_tasks{job="ipx"}', ref="B", legend="runtime tasks"),
                           prom('ipx_deadair_playing{job="ipx"}', ref="C", legend="playing through DeadAir")],
   16, w=8)
y += 8
ts("Memory", [prom('ipx_process_resident_bytes{job="ipx"}', legend="resident")], 0, w=12, unit="bytes")
ts("Open files and sockets", [prom('ipx_process_open_fds{job="ipx"}', legend="open")], 12, w=12)
y += 8
# Jobs and queues (#195)
ts("Worker", [prom('max by (kind) (ipx_worker_job_seconds{job="ipx"})', legend="on a {{kind}} for"),
              prom('max(ipx_last_scan_age_seconds{job="ipx"})', ref="B", legend="since the last scan finished")],
   0, w=8, unit="s", desc="A job's time that only climbs, or no scan for over 10 minutes, means the worker is stuck; the healthcheck still passes.")
ts("Jobs done", [prom('sum by (kind) (increase(ipx_jobs_total{job="ipx"}[$__rate_interval]))', legend="{{kind}}")],
   8, w=8, bars=True, stack=True)
ts("Time on jobs", [prom('sum by (kind) (increase(ipx_job_seconds_total{job="ipx"}[$__rate_interval]))', legend="{{kind}}")],
   16, w=8, unit="s", bars=True, stack=True, desc="Seconds the worker spent on each kind of job in each interval.")
y += 8
ts("In flight", [prom('max(ipx_http_requests_in_flight{job="ipx"})', legend="web requests"),
                 prom('max(ipx_scan_feeds_fetching{job="ipx"})', ref="B", legend="feeds fetching"),
                 prom('max(ipx_downloads_active{job="ipx"})', ref="C", legend="downloads"),
                 prom('2 - max(ipx_torrent_slots_free{job="ipx"})', ref="D", legend="torrents")],
   0, w=8)
ts("Download speed", [prom('sum(rate(ipx_download_bytes_total{job="ipx"}[$__rate_interval]))', legend="downloading")],
   8, w=8, unit="Bps")
ts("Backlogs", [prom('max(ipx_deadair_backlog{job="ipx"})', legend="DeadAir to look at"),
                prom('max(ipx_feed_retries{job="ipx"})', ref="B", legend="feeds to retry a lookup"),
                prom('max(ipx_event_queue{job="ipx"})', ref="C", legend="live updates unread"),
                prom('sum(increase(ipx_events_missed_total{job="ipx"}[$__rate_interval]))', ref="D", legend="live updates missed")],
   16, w=8)
y += 8
ts("DeadAir on a file", [prom('max(ipx_deadair_busy_seconds{job="ipx"})', legend="for")], 0, w=12, unit="s",
   desc="How long DeadAir has been on the file it is analysing; a few seconds each.")
ts("Artwork", [prom('max(ipx_art_cache_bytes{job="ipx"}) / max(ipx_art_cache_limit_bytes{job="ipx"})', legend="full"),
               prom('sum(increase(ipx_art_requests_total{job="ipx", result="hit"}[$__rate_interval])) / '
                    'sum(increase(ipx_art_requests_total{job="ipx"}[$__rate_interval]))', ref="B", legend="hit rate"),
               prom('sum(increase(ipx_art_evicted_total{job="ipx"}[$__rate_interval]))', ref="C", legend="images evicted")],
   12, w=12, unit="percentunit",
   desc="Full sits near 100% once the cache has filled, since each sweep trims it to fit. Hit rate is the share served from disk: "
        "the rest was fetched from the publisher. Evicted, on the right, is images each sweep threw out to stay under the "
        "limit: many at every sweep, with a falling hit rate, means the limit is too small.")["fieldConfig"]["overrides"] = [
    {"matcher": {"id": "byName", "options": "images evicted"},
     "properties": [{"id": "unit", "value": "short"}, {"id": "custom.axisPlacement", "value": "right"},
                    {"id": "custom.drawStyle", "value": "bars"}, {"id": "custom.fillOpacity", "value": 60}]}]
y += 8

# ---- Traces
row("Traces")
for x, title, q in [(0, "Recent traces", TRACES + "}"),
                    (12, "Slow traces (over 2s)", TRACES + " && duration > 2s}")]:
    panel("table", title, 12, 10, x,
          [{"refId": "A", "datasource": TEMPO, "queryType": "traceql", "query": q, "limit": 50,
            "tableType": "traces"}],
          fieldConfig={"defaults": {}, "overrides": []})
y += 10

# ---- Log
row("Log")
panel("logs", "Warnings and errors", 24, 10, 0, [loki(BAD + TEXT)],
      options={"showTime": True, "wrapLogMessage": True, "sortOrder": "Descending", "enableLogDetails": True})
y += 10
panel("logs", "Page and directory: warnings and errors", 24, 8, 0, [loki(OTHERS_BAD + ' | line_format "{{.container}} {{.level}}: {{.message}}{{.msg}}"')],
      options={"showTime": True, "wrapLogMessage": True, "sortOrder": "Descending", "enableLogDetails": True})
y += 8
panel("logs", "Log", 24, 12, 0,
      [loki(SEL + ' | json | __error__="" | path != "/api/events" | ev != "feed_skip" | ev != "status"'
            ' | message != "-> {\\"cmd\\":\\"status\\"}"' + TEXT)],
      description="Without the event stream's requests, not-due skips and healthcheck status calls.",
      options={"showTime": True, "wrapLogMessage": True, "sortOrder": "Descending", "enableLogDetails": True})

dash = {
    "uid": "ipx", "title": "iPX", "tags": ["ipx"], "timezone": "browser", "schemaVersion": 39,
    "time": {"from": "now-24h", "to": "now"}, "refresh": "1m", "editable": True,
    "templating": {"list": [
        {"name": "loki", "label": "Logs", "type": "datasource", "query": "loki", "current": {}, "hide": 0},
        {"name": "tempo", "label": "Traces", "type": "datasource", "query": "tempo", "current": {}, "hide": 0},
        {"name": "prometheus", "label": "Metrics", "type": "datasource", "query": "prometheus", "current": {}, "hide": 0},
    ]},
    "links": [{"title": "iPX", "type": "link", "url": "https://ipodderx.sdf1.net", "targetBlank": True}],
    "panels": panels,
}

if sys.argv[1:] == ["queries"]:
    for q, instant in QUERIES.items():
        print(json.dumps([q, instant]))
else:
    print(json.dumps(dash, indent=2))