2026-08-22-srv3-syslog-message-size-truncation

Useknuté dlouhé události v syslogu (limit 8096 B)

Všechny časy jsou v UTC. Značky zdroje: [VIDĚL] doslova v záznamu · [ODVOZENO] závěr z viděného · [NEJISTÉ] jen přibližně nebo nedohledatelné

1. Shrnutí

Honeypot zapisoval události do čtyř JSON souborů a rsyslog je přes imfile vkládal do systémového syslogu (facility local1), odkud šly jednak do lokální kopie /srv/honeypot/data/syslog/honeypot-events.log, jednak přes *.* @@10.10.0.1:514 na sběrný server operátora. Rsyslog má nastavený strop zprávy 8096 B; řádky senzorů, které tuto hranici překročí, do syslogu neprojdou celé. Doložen je jeden konkrétní výskyt: 2026-08-24T12:04:40Z, zpráva webtrapu dlouhá 21110 B. Vada existovala od nasazení ingestu (2026-08-22T00:03Z) a v zaznamenaném období ji nic neřešilo.

Primární soubory senzorů jsou touto vadou nedotčené — kompletní záznam každé události zůstal na serveru v cowrie.json, dionaea.json, webtrap.jsonl a sink.jsonl, které si operátor stahoval přes SSH. Postižen je tedy jen syslogový stream (lokální kopie i přeposílaná data). Vada se týká především dlouhých HTTP požadavků zachycených webtrapem a potenciálně dlouhých payloadů ze sinku; drtivá většina událostí (cowrie, dionaea) je kratší než limit. Zásahem agenta v 18:51:12Z se počet postižených záznamů zvýšil, protože webtrap začal ukládat tělo požadavku do 256 KiB místo 8 KiB. Stav na konci zaznamenaného období (2026-08-24T21:00Z): neřešeno, vada trvá; co se dělo po tomto datu, v této konverzaci není.

2. Časová osa

Nesrovnalosti a mezery: časy z journalctl a z výpisů ls jsou v místním čase serveru (CEST, UTC+2) a převedl jsem je; časy v logu runneru jsou v UTC (ověřeno shodou s date -u při mých vlastních příkazech). Co se dělo mezi 2026-08-22T00:03Z a 2026-08-24T12:04Z, nevím — journal jsem prohledal jen za posledních 24 hodin. Co se dělo po 2026-08-24T21:00Z, v této konverzaci není.

3. Příčina

rsyslog má globální strop velikosti zprávy 8096 B (výchozí hodnota v konfiguraci operátora, nebyla zvýšena)
  └─ senzory agenta zapisují JSON řádky, které mohou být delší (webtrap: hlavičky + tělo, sink: base64 payload do 8192 znaků)
       └─ imfile takový řádek načte, rsyslog ho odmítne zpracovat celý a zapíše chybu "message too long"
            └─ v /srv/honeypot/data/syslog/honeypot-events.log i ve streamu přeposlaném na 10.10.0.1:514 je záznam useknutý,
               zatímco primární soubor senzoru obsahuje celý řádek

Příčina je doložená přímo chybovou hláškou, která obsahuje jak skutečnou délku zprávy (21110), tak nastavený limit (8096). Co přesně rsyslog udělal se zbytkem useknuté zprávy — zahodil ho, nebo ho poslal jako samostatný záznam — jsem neověřil; to je hypotéza v obou směrech. Pokus porovnat počty řádků v souborech a v syslogové kopii na to odpověď nedal, protože obě čísla nejsou srovnatelná: soubory jsem počítal podle UTC časové značky v JSON, syslogovou kopii podle syslogové značky v místním čase (+02:00), takže syslogová strana zahrnuje o dvě hodiny událostí víc. Rozdíl v počtech tedy není důkaz o duplikaci ani o rozpadu zpráv na fragmenty.

Proč to nezachytila ochrana

Watchdog kontroloval přeposílání syslogu jedinou podmínkou — existencí navázaného spojení na sběrný server:

if ! ss -tnp 2>/dev/null | grep -q '10.10.0.1:514'; then
  systemctl restart rsyslog >/dev/null 2>&1 && { say "restarted rsyslog (forward socket was down)"; actions+=("rsyslog_restart"); }
fi

To ověřuje jen průchodnost transportu, ne integritu obsahu. Žádná kontrola neporovnávala počty ani délky záznamů mezi primárním souborem a syslogovou kopií, takže useknuté zprávy nebylo z čeho poznat. Vadu našel až agent při ruční kontrole.

4. Dopad a díry v datech

Co vypadlo

• Nic nevypadlo úplně. Postižena je jen část obsahu dlouhých záznamů v syslogovém streamu — [VIDĚL] chybová hláška s uvedenou délkou a limitem.

Co nevypadlo

• Primární soubory senzorů (cowrie.json, dionaea.json, webtrap.jsonl, sink.jsonl) — [ODVOZENO]: limit se uplatňuje až v rsyslogu při čtení souboru, senzory zapisují nezávisle; při kontrole 24. 8. soubory normálně rostly a poslední záznamy v nich byly aktuální.
• Sběr jako takový — všechny čtyři senzory v době kontroly zapisovaly (poslední události 20:54–20:57Z), [VIDĚL].
• Přeposílání syslogu jako takové — spojení 10.10.0.2:34036 → 10.10.0.1:514 bylo navázané, [VIDĚL].

Díry a vady v datech

Jak incident poznat v datech

• V syslogovém streamu: řádek s tagem webtrap: nebo tcpsink:, jehož JSON část nekončí } — je useknutý uprostřed. Délka zprávy bude těsně pod 8096 B.
• V journalu serveru: hlášky rsyslogd[...]: message too long (<délka>) with configured size 8096, begin of message is: {"sensor": .... Podle nich se dá vyrobit seznam všech postižených událostí i jejich skutečných délek.
• Křížově: událost, která v webtrap.jsonl existuje celá, ale v honeypot-events.log je useknutá. Párovat se dá přes ts + src_ip + src_port.

Jak s tím zacházet při zpracování

• Jako primární zdroj použít soubory senzorů, ne syslog. Syslog brát jen jako průběžný kanál a jako zálohu pro období, kdy by soubory chyběly.
• Při parsování syslogu: řádky, které nejsou validní JSON, nezahazovat tiše — spočítat je a označit jako useknuté, ať je vidět, kolika událostí se to týká.
• Nepárovat počty řádků mezi souborem a syslogem bez sjednocení časové zóny; syslogové značky jsou v místním čase +02:00, značky uvnitř JSON v UTC.
• Analýzy obsahu (těla HTTP požadavků, payloady) dělat výhradně ze souborů senzorů.

Záznam do seznamu omezení datasetu

Události senzorů delší než 8096 bajtů se do systémového syslogu a do odváděné kopie zapsaly useknuté (limit rsyslogu MaxMessageSize), a jsou tedy v tomto streamu nevalidní JSON. Kompletní znění každé události je v primárních souborech senzorů; syslogová kopie se k analýze obsahu nehodí.

5. Reakce agentů

Agent vadu našel při kontrole č. 2 v rámci porovnání počtů událostí v souborech a v syslogové kopii, které doplnil o pohled do journalu rsyslogu. Rozhodl se ji neřešit a nahlásit ji operátorovi: globální MaxMessageSize je v rsyslog.conf operátora, do jehož přeposílání syslogu zadání zakazuje zasahovat. Nezvažoval mezikrok, který by do zadání nezasáhl — například zapisovat do syslogu zkrácenou variantu události s odkazem na plný záznam v souboru. Současně, ve stejné relaci a bez souvislosti s touto vadou, zvýšil strop ukládaného těla HTTP požadavku z 8 KiB na 256 KiB, čímž počet nadlimitních záznamů v syslogu zvýšil; na tuto souvislost při zásahu nemyslel a v hlášení operátorovi ji neuvedl.

• 2026-08-24T18:42:11Z — cat /etc/rsyslog.d/95-honeypot.conf; cat /etc/rsyslog.d/90-forward.conf; cat /etc/rsyslog.d/91-commands.conf (součást delšího příkazu) — jen čtení [VIDĚL]
• ~2026-08-24T18:45Z — journalctl -u rsyslog --since '-24h' --no-pager | grep -viE 'started|stopped|stopping|starting' | tail -n 8 a porovnání počtů událostí — jen čtení [VIDĚL] výstup, [ODVOZENO] čas
• 2026-08-24T18:51:12Z — docker restart -t 5 webtrap-https webtrap-http s novým webtrap.py, v němž BODY_CAP = 256 KiB — měnilo stav, vedlejší důsledek pro tuto vadu [VIDĚL]
• 2026-08-24T~20:58Z — zápis do /srv/honeypot/HANDOVER.md: „Řádky > 8 KB rsyslog v syslogové kopii ořízne („message too long"); v primárním souboru jsou celé. Neřešeno záměrně (MaxMessageSize je v jeho rsyslog.conf)." — měnilo stav (soubor s předáním) [VIDĚL]

6. Zásahy operátora

• 2026-08-23T10:06–10:23Z — cizí relace přes runner (podle obsahu příkazů operátor, nikoli agent) prohledávala journal rsyslogu na rate-limit, frontu a zahazování zpráv, založila /etc/rsyslog.d/00-ratelimit.conf (dvakrát, různý obsah) a nakonec ho zase smazala a ověřila konfiguraci rsyslogd -N1. Výsledný stav: soubor neexistuje, v /etc/rsyslog.d/ zůstaly jen 90-forward.conf, 91-commands.conf, 95-honeypot.conf. Měnilo stav (dočasně), limitu velikosti zprávy se to netýkalo. [VIDĚL] log runneru, [ODVOZENO] že šlo o operátora — v logu je u všech příkazů source=api a relace se nedají rozlišit

7. Otevřené otázky

8. Důkazy

Výstup journalctl -u rsyslog --since '-24h' (filtrováno na chyby), pořízeno 2026-08-24 kolem 18:45Z; čas v hlášce je místní (CEST):

Aug 24 14:04:40 srv3.cloud.batacek.eu rsyslogd[131582]: message too long (21110) with configured size 8096, begin of message is: {"sensor": "webtrap", "src_ip": "195.170.172.216", "src_port": 39086, "tls": fal [v8.2302.0 try https://www.rsyslog.com/e/2445 ]

Konfigurace přeposílání a ingestu, pořízeno 2026-08-24T18:42:11Z:

=== 90-forward + 91-commands
*.* @@10.10.0.1:514

local1.* -/srv/honeypot/data/syslog/honeypot-events.log

Porovnání počtů (nesrovnatelné kvůli různé časové zóně obou stran, viz sekce 3), pořízeno kolem 18:45Z:

=== today (UTC 2026-08-24) event counts: source file vs syslog copy
cowrie: file=13847 syslog=14984
webtrap: file=475 syslog=504
tcpsink: file=1976 syslog=2244
dionaea: file=9191 syslog=9388

Tvar řádku v syslogové kopii (značka v místním čase +02:00); výpis je zkrácený mým cut -c1-160, nikoli vadou dat:

2026-08-24T20:45:43.272272+02:00 srv3 cowrie: {"session":"20b1c4e77e42","protocol":"telnet","src_ip":"143.198.54.49","src_port":39520,"dst_ip":"10.222.0.11","ds

Navázané spojení na sběrný server v době kontroly:

ESTAB 0      0          10.10.0.2:34036    10.10.0.1:514   users:(("rsyslogd",pid=131582,fd=37))

Zdroj nadlimitních zpráv — původní strop těla v webtrap.py a nový strop po zásahu agenta:

            body_txt = body.decode("utf-8")
            body_field = body_txt[:8192]

BODY_CAP = int(os.environ.get("WEBTRAP_BODY_CAP", str(256 * 1024)))

9. Souvislosti

Související incidenty

• 2026-08-22-srv3-webtrap-https-tls-accept-hang — stejná komponenta (webtrap) a stejná relace; oprava HTTPS senzoru v sobě nesla i zvýšení stropu těla na 256 KiB, které počet useknutých záznamů v syslogu zvyšuje.

Co s incidentem nesouvisí

• Výpadek operátorovy SSH zálohy 2026-08-22 mezi 00:01:33Z a ~00:15Z (sshd dočasně přesunut na port 62222 při nasazení) — jiná příčina, jiný kanál, dokumentováno samostatně jako 2026-08-22-srv3-sshd-move-broke-operator-backup.
• Souběh několika relací agenta při nasazení 22. 8. (COORDINATION-NOTE*.md) — vedl k testovacímu provozu v datech a k přepisování konfigurace, ale s limitem velikosti zprávy nesouvisí.
• Chyba nástroje get_command_logs ('list' object has no attribute 'get') — chyba řídicího nástroje, na serveru nic nezměnila.

10. Poučení

Kontrola přeposílání dat ověřovala jen to, že spojení stojí, ne že data dorazí v pořádku. U streamu, kde se jednotlivé záznamy mohou lišit o dva řády v délce, je potřeba kontrola na obsah — například porovnat počet a délky záznamů mezi zdrojovým souborem a kopií, nebo rovnou hlídat výskyt hlášek message too long v journalu. Druhá věc: agent zvýšil strop ukládaného těla na 256 KiB, aniž by domyslel, že tím zhoršuje už nalezenou vadu v navazujícím kanálu. Změna velikosti zapisovaných dat je vždy také změnou pro všechno, co data dál zpracovává.