p24-infra Docs

pinbox24-no-logs-false-positive

7 min read

Playbook: Pinbox24 “No Logs” P1 — triage from bms-4 via Mezmo

Trigger: P1 GitHub issue titled [P1] Pinbox24 no logs - bms-1 (auto-generated by the mezmo-alert-router n8n workflow, Sc2AKCdslinnSvWs). The underlying Mezmo absence alert keys on app:pm2_v42-prod (and w3/w4 worker variants) being absent for >24h on bms-1. Host of record: bms-1 (94.23.26.113, OVH hostname ns367522) — Pinbox24 production. Time budget: P1 — resolve within 1h.

Key fact: these no-logs alerts have a history of firing spuriously (alert storm tracked in #1310 / PR #1379, which added GH-issue dedup to mezmo-alert-router). Most fire as false positives where logs are in fact flowing. Confirm before assuming a real outage.

Mezmo is authoritative — you usually don’t NEED to SSH bms-1

The alert condition is “no Pinbox24 logs reaching Mezmo”, so Mezmo itself is the authoritative source of truth. Query Mezmo directly from bms-4 (Step 1) — if recent pm2_v42-prod lines exist, the alert is a false positive regardless of anything on bms-1.

Update (#5719, 2026-08-06): the bms-4 infra-task worker CAN now SSH bms-1 as root. The old “#1270: bms-1 unreachable from bms-4 / AI runners” claim is stale — bms-1 is Pinbox24 production and the infra-task worker holds the stack SSH grant (see docs/w3-w4-stack-operations.md). So the direct diagnostic in Step 3 (docker ps / pm2 status / mezmo-agent logs) IS runnable from a bms-4 infra-task worker, not human-workstation-only. Still start with the Mezmo query below — it’s faster and authoritative — but you no longer have to escalate to a human just to reach the box.

Step 1 — Confirm logs are (or aren’t) reaching Mezmo

Run from any host that can decrypt SOPS (e.g. bms-4, vps-i1). The Mezmo service key is P24_INFRA_MEZMO_SERVICE_KEY in secrets/monitoring.env.sops.

cd /opt/p24-infra
export SOPS_AGE_KEY_FILE="$HOME/.age/p24-infra-keys.txt"
set -a; eval "$(sops --decrypt --input-type dotenv --output-type dotenv \
  secrets/monitoring.env.sops 2>/dev/null | grep '^P24_INFRA_MEZMO_SERVICE_KEY=')"; set +a
 
python3 - <<'PY'
import os, requests, datetime as dt
from datetime import datetime, timezone
H={"Authorization":f"Token {os.environ['P24_INFRA_MEZMO_SERVICE_KEY']}"}
now=datetime.now(tz=timezone.utc); start=now-dt.timedelta(hours=2)
frm=int(start.timestamp()*1000); to=int(now.timestamp()*1000)
latest=0; n=0; pag=None; pages=0
while pages<12:
    p={"from":frm,"to":to,"size":10000}
    if pag: p["pagination_id"]=pag
    j=requests.get("https://api.mezmo.com/v2/export",headers=H,params=p,timeout=90).json()
    for l in j.get("lines",[]):
        if l.get("_host")=="bms-1" and "pm2_v42-prod" in (l.get("_app") or ""):
            n+=1; latest=max(latest,l.get("_ts",0))
    pag=j.get("pagination_id"); pages+=1
    if not pag or not j.get("lines"): break
if latest:
    age=(now.timestamp()-latest/1000)/60
    print(f"pm2_v42-prod lines (2h): {n}  latest={dt.datetime.fromtimestamp(latest/1000,tz=timezone.utc).isoformat()}  age={age:.1f} min")
else:
    print("NO pm2_v42-prod lines from bms-1 in the last 2h — possible REAL outage")
PY

Note: the mezmo-manage.py usage subcommand 400s on the current Mezmo plan (/v2/usage/apps unsupported) — use the /v2/export query above instead. The export endpoint returns a JSON object {"pagination_id":..., "lines":[...]} (NOT NDJSON); each line carries _host, _app, _ts (ms), _line.

Decision:

  • Recent lines exist (age < ~30 min) → FALSE POSITIVE. Logs are flowing; the alert tripped on a transient gap or stale 24h window. Go to Step 2 (close).
  • No lines in 2h → possible real outage. Go to Step 3 (escalate — needs bms-1 access).

Step 2 — False positive: document + close

Post a resolution comment with the evidence (line count + latest timestamp + a sample line), then close the issue. No code/config change is required.

gh issue comment <N> --repo radieu/p24-infra --body-file resolution.md
gh issue close  <N> --repo radieu/p24-infra --reason completed

If the alert is firing too often, the durable fix is in mezmo-alert-router dedup (#1310/PR#1379) and/or tuning the Mezmo absence-alert window — not on bms-1.

Nologs Suppression Guard (#4130, hardened #5704). mezmo-alert-router already suppresses most of these false positives before they reach GH: its first node cross-checks Prometheus and drops the alert when logs are confirmed flowing. Two #5704 hardenings apply:

  • Option 1 (retry): it is fail-open, and now retries the Prometheus query (3× / 600ms backoff) before failing open so a single transient query blip no longer leaks a false positive (#5700).
  • Option 2 (per-container repoint, #5605): the ground truth is now sum(pinbox24_backend_log_lines_5m_total) (v42-prod / W4 + v32-prod / W3), not the legacy unlabeled pinbox24_log_lines_5m_total (v42-prod only) — so a W3-only-active quiet period on W4 no longer defeats suppression. Summing is safe because the native View is host-level and genuine per-backend gaps are caught independently by the Pinbox24NoLogs Prometheus rule below.

If a false positive still opens an issue, verify Prometheus was reachable at fire time. Guard details: docs/n8n-operations.md §Nologs Suppression Guard.

Step 3 — Real outage: diagnose on bms-1

A bms-4 infra-task worker can SSH bms-1 as root directly (#5719) — run the checks below itself; escalate to a human-action issue only if the box is genuinely unreachable or the fix needs a credential the worker can’t touch. Run, on bms-1 (94.23.26.113):

systemctl status logdna-agent              # is the agent running?
journalctl -u logdna-agent --since '1h ago' --no-pager | tail -40
grep -E '^key|^logdir|^tags|^hostname' /etc/logdna.conf   # config sanity
pm2 status                                 # are the Pinbox24 pm2 apps up?
docker ps --format '{{.Names}}\t{{.Status}}'

Common causes (see docs/mezmo-operations.md §Troubleshooting): logdna-agent stopped / key invalid → systemctl restart logdna-agent; wrong logdir in /etc/logdna.conf; Mezmo ingestion quota exceeded.

Also send a Discord alert via P24_DISCORD_INFRA_SCRIPTS_ERRORS_WEBHOOK_URL (red) per the Error Notification Standard.

Variant: Pinbox24NoLogs Prometheus alert (mezmo-exporter path) — #2492

The n8n mezmo-alert-router P1 above is one of two independent “no logs” signals. The other is the Prometheus alert Pinbox24NoLogs (monitoring/prometheus/rules/pinbox24.yml), which fires for 15m on pinbox24_backend_log_lines_5m_total{container=...} == 0 per backend (#5605). That metric is set by the mezmo-exporter (mezmo-exporter:9250 on vps-i1), which runs the Mezmo /v1/export query app:pm2_<container>_production_out.log for every BACKEND_CONTAINERS entry (v42-prod / W4 and v32-prod / W3) every 60s. Before #5605 the alert read the unlabeled pinbox24_log_lines_5m_total (v42-prod only), so a W3-only logging gap went undetected; the unlabeled gauge is still emitted (kept in sync with the v42-prod series) for legacy dashboards. The firing alert names the affected backend via its container label.

Critical failure mode (#2492, 2026-07-01/02): the exporter’s _mezmo_query returns [] on any Mezmo API error (4xx/5xx, timeout, or a missing/invalid P24_INFRA_MEZMO_SERVICE_KEY), which forces pinbox24_log_lines_5m_total to 0 — indistinguishable from a genuine no-logs condition. In this incident a broken exporter auth header kept the metric stuck at 0 for ~20h (fixed by PR #2596), so Pinbox24NoLogs fired and its “check log forwarding GH #1339” annotation sent triage down the wrong path. Logs were flowing into Mezmo the entire time, correctly tagged pm2_v42-prod_production_out.log on host bms-1.

Diagnose before assuming a forwarding outage — check the exporter’s own health first:

# 1. Is the exporter hitting Mezmo API errors? (non-zero / rising = exporter fault, NOT log forwarding)
#    Prometheus needs basic auth: PROMETHEUS_BASIC_AUTH_USER / _PASSWORD from secrets/monitoring.env.sops
curl -sS -u "$PU:$PP" -G https://prometheus.vps-i1.infra.zintegrowana.online/api/v1/query \
  --data-urlencode 'query=mezmo_exporter_api_errors_total'
curl -sS -u "$PU:$PP" -G https://prometheus.vps-i1.infra.zintegrowana.online/api/v1/query \
  --data-urlencode 'query=pinbox24_backend_log_lines_5m_total'   # per-backend (#5605); {container="v32-prod"} == 0 = W3-only gap
 
# 2. Confirm logs really are in Mezmo (v1/export, NDJSON, matches the exporter's own query):
#    KEY=P24_INFRA_MEZMO_SERVICE_KEY from secrets/monitoring.env.sops; window = last 5 min
curl -sS -G https://api.mezmo.com/v1/export -H "Authorization: Token $KEY" \
  --data-urlencode "from=$(( $(date +%s%3N) - 300000 ))" --data-urlencode "to=$(date +%s%3N)" \
  --data-urlencode 'query=app:pm2_v42-prod_production_out.log' --data-urlencode 'size=10000' | grep -c '"_ts"'
  • mezmo_exporter_api_errors_total rising AND Mezmo has recent lines → exporter fault (auth/key/ network), not a Pinbox24 outage. Fix the exporter (see docs/mezmo-operations.md, PR #2596 auth pattern Authorization: Token), rebuild it on vps-i1, and the metric self-heals. As of #2492 the dedicated MezmoExporterApiErrors alert now surfaces this case directly, and Pinbox24NoLogs is gated with and increase(mezmo_exporter_api_errors_total[10m]) == 0 so it no longer misfires while the exporter is degraded.
  • Errors flat (0) AND Mezmo returns 0 lines for 5 min → genuine no-logs; go to Step 3 (bms-1 access required — the mezmo-exporter query variant does not change that).

Mezmo API-version note: the mezmo-exporter uses /v1/export (NDJSON, one envelope per line with _app/_host/_file/_line); the n8n P1 diagnostic in Step 1 above uses /v2/export (JSON {"lines":[...]}). Match the exporter’s /v1 form when reproducing Pinbox24NoLogs.

References

  • docs/mezmo-operations.md — full Mezmo / logdna-agent config + troubleshooting (alerts at § “Alert definitions”: No logs from Pinbox24 w3/w4 longer than 24 hours)
  • docs/n8n-operations.md §mezmo-alert-router — alert→Discord/GH routing
  • #1310 / PR #1379 — no-logs alert storm + dedup fix
  • #1270 — bms-1 unreachable from bms-4 (no agent SSH key)

Graph View

Backlinks