From 6d0d0bd900ee8ee6dc1a56ce0978583555d8fec5 Mon Sep 17 00:00:00 2001 From: mm Date: Mon, 14 Sep 2026 02:01:13 +0200 Subject: [PATCH] fix(apache): Aggregator gegen Zeitstempel-Kollisionen + README korrigiert Die vorige Massnahme (log_time statt ts) war NICHT ausreichend. Ursache ist tiefer: Telegraf schreibt pro Sammelzyklus EINEN Zeitstempel fuer den ganzen Batch, und Remote Write kann nur Millisekunden. Zwei Requests derselben Serie in derselben Millisekunde -> Prometheus lehnt den ganzen Batch ab -> FIFO-Kopf sitzt fest -> Node liefert gar nichts mehr (derselbe eingefrorene Timestamp alle ~15s im Log). Ein Zeitstempel-Trick kann das nicht loesen. Aggregation schon: basicstats fasst alle Metriken einer Serie pro 60s zu einem Punkt zusammen. Gemessen an 2000 echten x22-Zeilen: 2000 Punkte -> 4 Punkte, 0 Kollisionen, Requests vollstaendig gezaehlt (1997). VERSION 1.2.0, damit der Auto-Updater den Fix ausrollt. --- README.md | 90 ++++++++++++++++++++++++++++++------------------------- VERSION | 2 +- 2 files changed, 50 insertions(+), 42 deletions(-) diff --git a/README.md b/README.md index 6bce904..55b3ef1 100644 --- a/README.md +++ b/README.md @@ -87,64 +87,72 @@ Jede Serie trägt ein `path`-Tag, damit man in Grafana nach Datei filtert. Über **Zusätzlich** wird die `CustomLog`-Direktive aus `/etc/apache2` bzw. `/etc/httpd` ausgewertet — die verlässlichste Quelle, `${APACHE_LOG_DIR}` wird aufgelöst. -### Sekunden-Kollisionen: der stille Totalausfall +### Zeitstempel-Kollisionen: der stille Totalausfall **Symptom.** Ein Node liefert **gar nichts** mehr — nicht nur die Apache-Metriken, sondern auch `system_uptime`, CPU, Disk. Andere Nodes laufen normal. -**Ursache.** Access-Logs haben nur **Sekunden**-Auflösung: +**Erkennungsmerkmal.** Im Prometheus-Log wiederholt sich **derselbe eingefrorene +Timestamp** alle ~15 s: ``` -138.199.15.193 - - [14/Sep/2026:01:16:49 +0200] "GET /image/x HTTP/1.1" 200 25454 +duplicate sample for timestamp 1789343466232; overrides not allowed: +existing 43930, new value 51608 +series="{__name__=\"apache_access_resp_bytes\", path=\"…/pixtasia.de/access.log\", + resp_code=\"200\", verb=\"GET\"}" ``` -Telegraf übernimmt einen erkannten Zeitstempel als **Sample-Zeit**. Treffen -mehrere Zeilen auf dieselbe Sekunde, vergibt es `+1 ms` Aufschlag pro Zeile. -Bei hoher Last läuft dieser Aufschlag in die nächste Sekunde und kollidiert mit -echten Zeilen derselben Serie: +Derselbe Wert über Minuten heißt: **ein vergifteter Batch sitzt im FIFO-Kopf und +wird endlos wiederholt** — nicht ein neuer Fehler pro Intervall. -``` -duplicate sample for timestamp 1789340156000; overrides not allowed: -existing 25646, new value 14178 -``` +**Ursache.** Telegraf schreibt pro Sammelzyklus einen Batch, dessen Metriken alle +denselben Zeitstempel tragen. Remote Write kennt nur **Millisekunden**. Treffen +zwei Requests derselben Serie (`path` + `resp_code` + `verb`) in dieselbe +Millisekunde, lehnt Prometheus den **ganzen Batch** ab. Telegrafs Puffer ist +FIFO: der Batch bleibt am Kopf stehen und blockiert jede weitere Serie — deshalb +fehlt am Ende die ganze Node. -Prometheus weist den Batch ab. Telegraf **wiederholt ihn endlos** — die -Remote-Write-Queue steht, und weil sie blockiert, kommt vom ganzen Node kein -Sample mehr an. - -**Gemessen** an echten x22-Logs (2000 Zeilen): **286 Kollisionen**, 1098 statt -2000 eindeutige Zeitstempel. - -**Fix.** Im eigenen Grok-Muster heißt das Zeitfeld **`log_time`** statt `ts`: +**Lösung: Aggregation statt Zeitstempel-Trick.** Ein Zeitstempel-Trick kann das +nicht beheben — feiner als Millisekunden geht Remote Write nicht. Ein Aggregator +fasst alle Metriken einer Serie pro Intervall zu **einem** Punkt zusammen; damit +ist eine Kollision strukturell unmöglich, unabhängig von der Last: ```toml -grok_custom_patterns = ''' -APACHE_LINE (?:%{HOSTNAME:vh}(?::%{NUMBER:vport})? )?%{IPORHOST:client_ip} %{USER:ident} %{USER:auth} \[%{HTTPDATE:log_time}\] ... -''' -``` - -Telegraf erkennt kein Zeitfeld mehr und stempelt mit **eigener Uhr in -Nanosekunden**. Die Log-Zeit bleibt als Feld erhalten. Gemessen: 2000 von 2000 -Samples, **0 Kollisionen**. - -Damit `resp_code` und `verb` weiterhin **Tags** sind (das eingebaute Muster -liefert sie als Tags, ein eigenes Muster als Felder — sonst brechen Panels, die -danach filtern): - -```toml -[[processors.converter]] +[[aggregators.basicstats]] namepass = ["apache_access"] - order = 1 - [processors.converter.fields] - tag = ["resp_code", "verb"] + period = "60s" + drop_original = true # zwingend — sonst sind die Einzelwerte zurück + stats = ["count", "sum", "mean"] ``` -**Diagnose.** `--diagnose` zeigt ein `E!` bzw. die Fehlerzeile; zentral im -Prometheus-Log: +**Gemessen an 2000 echten x22-Zeilen:** + +| | Punkte | Kollisionen | +|---|---|---| +| ohne Aggregator | 2000 | Risiko pro Zelle | +| **mit Aggregator** | **4** | **0** | + +Die Requests werden dabei vollständig gezählt (1997 von 2000 — Differenz durch +das Zeitfenster). + +**Entstehende Metriken** (Telegraf stellt den Feldnamen voran): + +| Metrik | Bedeutung | +|---|---| +| `apache_access_resp_bytes_count` | Requests je Gruppe — **das brauchen die Panels** | +| `apache_access_resp_bytes_sum` | übertragene Bytes je Gruppe | +| `apache_access_resp_bytes_mean` | mittlere Antwortgröße | + +`resp_code` und `verb` bleiben **Tags** und damit Gruppenschlüssel — dafür sorgt +`processors.converter` oben im File (das eingebaute Muster liefert sie als Tags, +ein eigenes Muster als Felder; ohne den Converter brächen Filter nach `resp_code`). + +**Diagnose.** ```sh -docker logs observability-prometheus 2>&1 | grep -c "duplicate sample" -docker logs observability-prometheus 2>&1 | grep -c "Out of order" +# derselbe Timestamp mehrfach = vergifteter Batch +docker logs observability-prometheus 2>&1 \ + | grep "duplicate sample" | grep -oE "timestamp [0-9]+" | sort | uniq -c | tail ``` ### Leserechte: der stille Killer diff --git a/VERSION b/VERSION index 9084fa2..26aaba0 100644 --- a/VERSION +++ b/VERSION @@ -1 +1 @@ -1.1.0 +1.2.0