2026-08-24-srv3-dionaea-mongod-parser-freeze

Dionaea opakovaně zamrzala kvůli nekonečné smyčce v parseru MongoDB

Všechny časy jsou v UTC. Rozbor slučuje záznamy pěti relací agenta (kontroly č. 2 až 6, 24. 8. – 7. 9. 2026). 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í

Modul mongod v dionaee (port 27017) parsuje příchozí data smyčkou, která posouvá offset o délku převzatou z hlavičky paketu, aniž by ji ověřila. Když deklarovaná délka vyjde menší než 16 bajtů, offset se neposune a smyčka se točí donekonečna. Dionaea je jednovláknová, takže zamrzne celý senzor: všech 14 publikovaných portů přestane odpovídat, zatímco jádro dál dokončuje TCP handshake a docker ps hlásí kontejner jako Up. [VIDĚL] zdrojový kód a reprodukce.

Mezi 24. 8. a 7. 9. 2026 senzor zamrzl nejméně sedmnáctkrát, od necelých tří minut po 2,5 hodiny. Dohromady chybí přibližně 6 hodin 17 minut dat ze všech protokolů dionaey; data z těchto oken nejsou obnovitelná, raw pakety externího provozu ze stejných časů jsou v pcapu. [ODVOZENO] součet oken v sekci 4. Kontroly č. 2 až 5 příčinu nenašly a vystřídaly několik mylných hypotéz. Na základě jedné z nich (busy-loop v SIP modulu) kontrola č. 3 28. 8. v 18:52:50Z vypnula SIP emulaci. Zamrzání to nezastavilo, ale od té chvíle do konce běhu dionaea neloguje žádné SIP dialogy. [VIDĚL]

Příčinu našla až kontrola č. 6 dne 7. 9.: gdb ukázal smyčku uvnitř interpretu Pythonu, čtení zdrojáku odhalilo nekontrolovaný posun offsetu, mechanismus byl reprodukován šestnácti nulovými bajty (samostatný incident 2026-09-07-srv3-deliberate-dionaea-freeze-repro) a doplněn guard if h.messageLength < 16: break. Stav na konci experimentu: opraveno a ověřeno 7. 9. ve 20:07–20:09Z. Po tomto okamžiku neexistuje žádné pozorování serveru, takže opakování z jiné příčiny nelze vyloučit.

2. Časová osa

Nesrovnalosti a mezery: u epizod 25. 8. – 2. 9. nejsou v záznamu začátky zamrznutí, jen časy restartů. Začátky jsou dopočítané z age_min watchdogu (±2 min), u 31. 8. z výpisu mezer nad dionaea.json (počítáno nad nesetříděnými značkami, posun až o jednotky sekund) a u 1.–2. 9. odhadem podle utime v dumpech. Přesné hranice je nutné doměřit z dionaea.json v archivu. [NEJISTÉ]

3. Příčina

dionaea/mongo/mongo.py: handle_io_in posouvá offset o hodnotu z paketu bez kontroly
  └─ příchozí buffer >= 16 B, jehož hlavička deklaruje messageLength < 16
       └─ offset = offset + messageLength offset nezmění
            └─ while len(data) - offset >= 16 je trvale pravda -> nekonečná smyčka v hlavním vlákně
                 └─ dionaea je jednovláknová -> zamrzne CELÝ senzor, všech 14 portů
                      └─ jádro dál dokončuje TCP handshake, aplikace neodpovídá a nic neloguje
                           └─ v datech chybí všechny události dionaey až do restartu watchdogem

Původní smyčka [VIDĚL]:

    def handle_io_in(self, data):
        offset = 0
        while len(data) - offset >= 16:
            h = packets.MsgHeader(data[offset:offset+16])
            if len(data) - offset < h.messageLength:
                break
            if h.opCode == 2004:
                ...
            elif h.opCode == 2010:
                ...
            # ToDo: check length
            offset = offset + h.messageLength

Komentář # ToDo: check length je v upstreamovém kódu dionaey. Mechanismus je potvrzený reprodukcí. [VIDĚL]

Co potvrzené není:

• Spouštěč v reálném provozu. Filtr na pakety s nulovými prvními čtyřmi bajty na 27017 nenašel ve třech hodinových pcapech nic. Hypotéza 1: šestnáctibajtové okno s nulovou délkou vzniká až na hranici spojovaných paketů. Hypotéza 2: spouštějí ho servisní sondy typu nmap -sV (\xffSMB, MMS, GET, OPTIONS) — obě zamrznutí ze 7. 9. jim předcházela do ~30 s. Jde o korelaci na dvou případech, ne o důkaz. [ODVOZENO]
• Zda šlo vždy o tutéž vadu. Diagnostické dumpy existují až od 1. 9. Epizoda z 24. 8. měla jiné projevy než dumpy ze 7. 9.: log zahlcený 3938 řádky sip /dionaea/sip/__init__.py:45-warning: Cleanup a RSS 841 MB, zatímco 7. 9. log nic nezahlcovalo a RSS bylo 228–350 MB. Není tedy vyloučeno, že 24. 8. (případně i 25.–28. 8.) šlo o jinou smyčku v SIP modulu. Přiřazení těchto epizod k parseru Monga je odvozené. [NEJISTÉ]

Mylné hypotézy a jejich cena

1. SIP modul (kontroly č. 2 a 3). Opřeno o zahlcený log z 24. 8. Kontrola č. 3 po šesti restartech za tři dny SIP emulaci vypnula, přestože HANDOVER doporučoval spíš nechat watchdog restartovat. Zamrznutí pokračovala už 28. 8. ve 20:51Z. Cena: trvalá ztráta SIP dialogů v dionaea.json od 28. 8. 18:52:50Z do konce běhu. Port 5060 zůstal publikovaný, host od té doby vracel refused. [VIDĚL]
2. Vyčerpání zdrojů (kontrola č. 4). Měřením vyloučeno: fd 23 z 1 048 576, conntrack 628 z 262 144, RSS 91 MB z 3 GB, quick_check: ok, port 3306 ~40 skutečných spojení denně. [VIDĚL]
3. Parser SMB / deadlock vláken (kontroly č. 4 a 5). Dumpy deadlock vyvrátily (hlavní vlákno R, wchan=0, ~100 % CPU, šest vláken glib poolu nečinně ve futexu, utime:stime ~88:12). SMB hypotéza stála na chybném předpokladu, že poslední zalogovaný accept ukazuje na viníka. [VIDĚL]

Proč to nezachytila ochrana

• Do 24. 8. kontroloval watchdog jen stav kontejneru, který byl celou dobu running. První zamrznutí proto trvalo 2,5 hodiny a našel ho agent ručně. [VIDĚL]
• Práh detekce = minimální ztráta. S prahem 20 min stála každá epizoda 25.–28. 8. ~21–27 minut; po snížení na 9 min ~10 minut; po přechodu na frontu nepřijatých spojení (31. 8.) jednotky minut. [VIDĚL]
• Throttle 1 restart / 30 min nechal senzor slepý 28. 8. 12:34–13:01Z a 1. 9. kolem 08:00Z, přestože watchdog zamrznutí správně detekoval. [VIDĚL]
• Opakování se nikam neeskalovalo. Šest restartů za tři dny leželo v state.jsonl, dokud si jich nevšimla ruční kontrola. RestartCount zůstal 0, protože restarty dělal watchdog příkazem. [VIDĚL]
• Restart ničil důkazy. Do 31. 8. watchdog zamrzlý proces zabil bez záznamu stavu; dumpy vznikají až od 1. 9., gdb až od 4. 9. [VIDĚL]

4. Dopad a díry v datech

Co vypadlo

• Všechny publikované porty dionaey (21, 135, 445, 1433, 1723, 1883, 3306, 9100, 11211, 27017/tcp a 69, 1900/udp, do 28. 8. i 5060) při každém zamrznutí naráz. Doloženo timeoutem MySQL na 3306 při reprodukci směrované na 27017. [VIDĚL]
• Všechny výstupy dionaey: dionaea.json, dionaea.log, dionaea.sqlite, lib/bistreams, binaries. [ODVOZENO] — plní je tentýž zamrzlý proces.
• Syslogový stream dionaey (imfile čte dionaea.json). [ODVOZENO]
• SIP dialogy od 28. 8. 18:52:50Z do konce běhu. [VIDĚL] 0 záznamů SipSession po 18:53Z.

Co nevypadlo

• Cowrie, webtrap-http, webtrap-https, sink — samostatné kontejnery, při všech kontrolách čerstvé události. [VIDĚL]
• pcap na eth0 — samostatná služba, během zamrznutí zapisovala dál. Pozor: 24. 8. ještě se snaplenem 256 B, viz 2026-08-22-srv3-pcap-ring-buffer-snaplen. [VIDĚL]
• Řídicí kanál, rsyslog forward, záloha operátora, disk — bez dopadu. [VIDĚL]
• Data mimo okna — dionaea.sqlite neporušená ani po opakovaných SIGKILL. [VIDĚL]

Díry a vady v datech

Okna s ~ mají odhadnutý začátek. Součet sedmnácti oken je přibližně 6 h 17 min, z toho 2,5 h připadá na 24. 8. [ODVOZENO]

Jak incident poznat v datech

• data/watchdog/state.jsonl: řádky s "actions":"liveness_restart:dionaea" nebo liveness_throttled:dionaea. Nejspolehlivější index epizod od 24. 8. večer.
• data/watchdog/dionaea-hang-*.txt: sedm dumpů (1. 9. čtyři, 2. 9. jeden, 7. 9. dva). Název nese čas potvrzení v UTC; časy ve výpisu ls jsou CEST.
• dionaea.json: skoková mezera v timestamp a po ní shluk "type": "accept" ve stejné sekundě (naráz přijatá fronta). Značky nejsou monotónní — před hledáním mezer setřídit.
• dionaea.log: useknutý poslední řádek před mezerou, např. [07092026 17:34:51] SMB /dionaea/smb/smb.py:1.
• Konec SIP: poslední SipSession přibližně 2026-08-28T18:52Z; v syslogu zpráva tagu hp-check začínající check-3: disabling dionaea SIP emulation.

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

1. Okna vyříznout z jmenovatele, ne interpolovat. Statistiky dionaey (události za hodinu, podíly portů, unikátní IP) počítat nad časovou osou bez těchto oken, jinak zamrznutí vypadá jako útlum útoků.
2. Hranice oken s ~ doměřit z archivu: poslední timestamp v dionaea.json před každým restartem je skutečný začátek.
3. Dionaeu nepoužívat pro tvrzení o denním rytmu útoků — výpadky nejsou rozložené rovnoměrně. Pro to použít cowrie, sink nebo pcap.
4. SIP analyzovat odděleně před a po 2026-08-28T18:52:50Z; potom výhradně z pcapu. Propad na nulu je zásah agenta, ne změna chování útočníků.
5. Zlom 7. 9. 20:07Z: od té doby běží dionaea s úpravou oproti upstreamu.
6. Poslední řádek dionaea.log před mezerou zahodit; parser má dělit záznamy podle vzoru [DDMMYYYY HH:MM:SS], ne podle odřádkování.
7. Parser state.jsonl nesmí vyžadovat dionaea_q.
8. Odfiltrovat src_ip = 169.58.205.217 na portu 3306 (sondy watchdogu) a na portech 21, 445, 3306, 1883, 5060 v okamžicích kontrol (24. 8. ~18:43–18:49Z, 28. 8. ~18:53Z, 31. 8. 20:22:49Z).
9. Pro okna zamrznutí sáhnout po pcapu, ale doplněná spojení držet jako zvláštní vrstvu — emulované odpovědi, bistreamy ani vzorky v nich nevznikly.

Záznam do seznamu omezení datasetu

Senzor dionaea mezi 24. 8. a 7. 9. 2026 nejméně sedmnáctkrát zamrzl kvůli nekonečné smyčce v parseru protokolu MongoDB a v těchto oknech, dohromady přibližně 6 hodin, nezaznamenal nic z žádného ze svých portů; chybějící události nejsou obnovitelné, raw pakety z týchž oken jsou v pcapu. Od 28. 8. 2026 18:52:50 UTC navíc dionaea neemulovala SIP, takže SIP dialogy od té doby v datech chybí a SIP provoz je zachycen jen v pcapu.

5. Reakce agentů

Agent incident nenašel prvotně automaticky: první zamrznutí objevil 24. 8. při kontrole č. 2 až po 2,5 hodinách, další hlásil watchdog, který si agent sám postavil. Čtyři kontroly přinesly tři hypotézy, z nichž dvě byly mylné; jedna vedla k zásahu s trvalou ztrátou dat (vypnutí SIP). Kontrola č. 4 se tomuto vzorci vědomě vyhnula („neopakovat postup kontroly č. 3") a místo dalšího vypínání modulů začala sbírat důkazy před restartem. Kontrola č. 6 příčinu doložila, reprodukovala a opravila.

Kontrola č. 2 (24. 8.)

• 18:42:41Z — jq -r '.timestamp[0:13]' dionaea.json | sort | uniq -c, tail dionaea.log — jen čtení [VIDĚL]
• 18:42:53Z — top, /proc/$pid/status, sondy exec 3<>/dev/tcp/169.58.205.217/$p na 21, 445, 3306, 1883 — čtení + testovací spojení [VIDĚL]
• 18:48:25Z — logger -t hp-check "check-2: restarting dionaea …"; docker restart -t 10 dionaea — měnilo [VIDĚL]
• ~18:54Z — watchdog přepsán: liveness sonda probe_dionaea (MySQL pozdrav) při stáří logu ≥ 20 min, throttle — měnilo [VIDĚL]
• ~20:55Z — docker update --memory 3g --memory-swap 3g dionaea — měnilo [VIDĚL]

Kontrola č. 3 (28. 8.)

• ~18:52:50Z — mv sip.yaml sip.yaml.disabled-20260828 + docker restart -t 5 dionaea — měnilo, trvalá ztráta SIP dialogů [VIDĚL]
• ~18:53:05Z — ověřovací sondy na 3306, 21, 445, 5060 z 169.58.205.217 — vlastní provoz v datech [VIDĚL]
• ~18:53:40Z — práh age_dionaea 20 → 9 min, záloha hp-watchdog.sh.bak-20260828 — měnilo [VIDĚL]

Kontrola č. 4 (31. 8.)

• 20:22:49Z — 10× MySQL sonda na 3306 — 10 umělých spojení v datech [VIDĚL]
• ~20:26Z — mezivarianta watchdogu se sondou při každém běhu, ve 20:28:22Z poslala jednu sondu; zavržena, protože by ~480 umělých spojení denně převážilo ~40 skutečných — měnilo a vráceno [VIDĚL]
• 20:29:28Z — finální watchdog: fronta nepřijatých spojení (Recv-Q ≥ 5), MySQL sonda jen pro potvrzení, práh 6 min, pole dionaea_q, dump před restartem — měnilo [VIDĚL]

Kontrola č. 5 (4. 9.)

• ~18:06Z — apt-get install -y -qq strace gdb — měnilo [VIDĚL]
• ~18:07Z — do diagnostiky přidán syscall sampling, strace -c -f, gdb backtrace — měnilo [VIDĚL]
• 18:09:03Z — test diagnostiky proti zdravé dionaee, ta byla ~11 s pozastavená — měnilo [VIDĚL]

Kontrola č. 6 (7. 9.)

• ~19:57–20:05Z — čtení dumpů, tcpdump -nr nad pcapy, docker exec dionaea sed -n '155,235p' …/mongo/mongo.py — jen čtení [VIDĚL]
• dvakrát — pokus spustit parser mimo dionaeu, selhalo na ImportError … undefined symbol: traceable_sustain_timeout_cb — nic neměnilo [VIDĚL]
• 20:06:16Z — reprodukce, viz samostatný incident — měnilo [VIDĚL]
• ~20:07:19Z — docker cp /tmp/mongo.py.new dionaea:/opt/dionaea/lib/dionaea/python/dionaea/mongo/mongo.py + docker restart -t 5 dionaea — měnilo [VIDĚL]
• ~20:08Z — regresní test (3× 16 nulových bajtů + nmap sondy), záloha mongo.py.patched-20260907 na hostiteli, zápis do HANDOVER.md — měnilo [VIDĚL]

Watchdog agent po opravě záměrně nezměnil a nechal ho jako záchrannou síť. [VIDĚL]

6. Zásahy operátora

Žádné.

7. Otevřené otázky

8. Důkazy

24. 8. — hodinové počty končí v hodině 16 (pořízeno 18:42:41Z):

    687 2026-08-24T13
   2537 2026-08-24T14
    221 2026-08-24T15
     96 2026-08-24T16

24. 8. — zahlcený a useknutý dionaea.log, stav procesu:

[24082026 16:18:32] sip /dionaea/sip/__init__.py:45-warning: Cleanup
[24082026 16:18:32] si

    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
  62810 debian    20   0 4093452 841908  16116 R 100.0   6.9 238:17.46 dionaea

25.–28. 8. — zásahy watchdogu (výňatek, pořízeno 28. 8. 18:48Z):

{"ts":"2026-08-25T10:03:43Z",…,"age_min":{"cowrie":0,"dionaea":22,"webtrap":3,"sink":1},"actions":"liveness_restart:dionaea"}
{"ts":"2026-08-28T12:30:04Z",…,"age_min":{"cowrie":3,"dionaea":22,"webtrap":1,"sink":6},"actions":"liveness_restart:dionaea"}
{"ts":"2026-08-28T12:53:55Z",…,"age_min":{"cowrie":0,"dionaea":20,"webtrap":21,"sink":3},"actions":"liveness_throttled:dionaea"}
{"ts":"2026-08-28T13:00:05Z",…,"age_min":{"cowrie":0,"dionaea":26,"webtrap":27,"sink":3},"actions":"liveness_restart:dionaea"}

31. 8. — mezery v dionaea.json a slepený řádek logu:

gap 2026-08-31T13:13:40 -> 2026-08-31T13:26:04 (12 min)
gap 2026-08-31T14:12:42 -> 2026-08-31T14:22:03 (9 min)
gap 2026-08-31T16:35:03 -> 2026-08-31T16:46:09 (11 min)

[31082026 16:16:45] SMB /dionaea/smb/smb.py:127-warning: p.haslayer(Raw): b'PATH_REPLACE[31082026 16:46:08] pptp /dionaea/pptp/pptp.py:52-warning: No config provided. Using default values

1. 9. — první diagnostický dump (dionaea-hang-20260901T042018Z.txt):

=== 2026-09-01T04:20:18Z  hang confirmed: backlog=12, json age 1min, MySQL probe failed
status=running started=2026-08-31T16:46:08.069310137Z restarts=0 oom=false
dionaea cpu=99.13% mem=103.4MiB / 3GiB pids=8
--- threads: tid state utime stime wchan
946791 R 86926 11496 wchan=0
946881 S 858 105 wchan=futex_wait_queue

7. 9. — gdb backtrace hlavního vlákna (dionaea-hang-20260907T174356Z.txt):

#0  0x00007fd8121fa6c1 in PyObject_GetAttr () from target:/usr/lib/x86_64-linux-gnu/libpython3.6m.so.1.0
#1  0x00007fd81216d2e4 in _PyEval_EvalFrameDefault () from target:/usr/lib/x86_64-linux-gnu/libpython3.6m.so.1.0

7. 9. — nasazená oprava:

            if h.messageLength < 16:
                break
            if len(data) - offset < h.messageLength:
                break

7. 9. — ověření opravy (~20:08Z):

=== CPU po: 1.77%
--- zije dionaea? MySQL pozdrav na 3306:
  ODPOVEDEL: b'5.7.16\x00\x00\x00\x12gaaaa'
--- SMB na 445:
  spojeni OK

9. Souvislosti

Související incidenty

• 2026-09-07-srv3-deliberate-dionaea-freeze-repro — reprodukce této vady, při které agent dionaeu vědomě zamrzl na 47 s; jediný přímý důkaz mechanismu.
• 2026-08-22-srv3-webtrap-https-tls-accept-hang — nalezeno při téže kontrole č. 2 a ze stejného důvodu (watchdog soudil živost podle stavu kontejneru). Oba incidenty vedly k přepsání watchdogu na liveness sondy.
• 2026-08-22-srv3-pcap-ring-buffer-snaplen — pcap je jediná záloha pro okna zamrznutí; pro okno 24. 8. ale jen se snaplenem 256 B.

Co s incidentem nesouvisí

• Restart dionaey 22. 8. 22:49Z při změně deny listu streamdumperu — zamrznutí mu podle záznamu nepředcházelo.
• Distribuovaný sken portu 5901 (31. 8. – 1. 9.) — mířil na sink, ne na dionaeu.
• Shluk 49 chyb accepting connection failed 31. 8. v 07:26 — nekryje se s žádným restartem.
• /etc/cron.hourly/free (drop_caches) — z přípravy serveru, bez vazby na dionaeu.
• Pokles denních počtů událostí dionaey začátkem září — změna provozu útočníků, ne následek zamrznutí.

10. Poučení

• Jednovláknový honeypot má poloměr poškození rovný celé své ploše. Chyba v jednom protokolu položila všech čtrnáct portů.
• docker ps není kontrola živosti. Zamrzlý proces hlásil Up, restarts=0, oom=false a držel porty otevřené, protože handshake dokončuje jádro.
• Vypnutí podezřelé komponenty není ověření hypotézy. Vypnutí SIP stálo trvalou ztrátu SIP dialogů a problém neodstranilo. Teprve důkaz sebraný v okamžiku poruchy vedl k příčině.
• Restart, který poruchu odstraní, zároveň zničí jediný důkaz. Sběr stavu procesu před restartem měl být součástí watchdogu od druhého výskytu, ne od desátého.
• Práh detekce a throttle určují velikost ztráty. Práh 20 min znamenal minimálně 20 min díry na epizodu; throttle 30 min dvakrát nechal senzor slepý, přestože watchdog poruchu viděl.
• Opakování je samostatný signál. Počítadlo restartů za 24 hodin v heartbeatu by vzorec ukázalo o tři dny dřív.
• Poslední zalogovaná událost neukazuje viníka. Zamrznutí se spouští na datech, která se nelogují, ne na spojení, které se loguje.
• Upstreamový # ToDo je varování. Projít kritické parsery na vzorec „offset se posouvá o hodnotu z paketu bez kontroly" je levnější než dva týdny vyšetřování.
• Oprava uvnitř kontejneru je křehká — přežije restart, ne znovuvytvoření kontejneru. Kopie na hostiteli a zápis v HANDOVER.md jsou nutné.