pátek 16. listopadu 2012

Shluky chyb - charakteristika a dopad

Před nedávnem jsem strávil den lovením chyby, která se projevovala následujícím záhadným způsobem. Odhlášení z GoodData se provádí HTTP požadavkem s metodou DELETE na resource reprezentující uživatelskou session. Na Internet Exploreru verze 10 docházelo k tomu, že prohlížeč zůstal viset přesně minutu při čekání na odpověď, aby vždy nakonec obdržel vnitřní chybu serveru.

Prvním krokem bývá zkontrolovat logy. Z logu na první pohled vyplývalo, že frontend server čekal minutu na odpověď z backend serveru a protože se nedostavila, odpověděl klientovi vnitřní chybou serveru. Zároveň bylo z logu vidět, že backend server přibližně ve stejný okamžik požadavek nakonec správně odbavil. Vlastní zpracování požadavku nikde nevázlo. První myšlenka, která mě napadla, byla že se jedná o deadlock na fronted serveru, který se uvolní po jedné minutě. Přes JMX konzoli jsem osolil logování klíčových komponent ve fronted serveru. Z detailních logů bylo patrné, že se požadavek nikde na frontendu nebrzdí. Na backend serveru detailní logování ukázalo, že minutové čekání není v žádných místech, kde by to člověk očekával, jako například databáze. Na řadu přišly dobře řízené výpisy stavu zpracování požadavku. Po hodině experimentování se podařilo izolovat místo čekání na řádek čtení těla HTTP uvnitř REST frameworku v backend serveru.

Kolegu napadlo, že by příčinou mohl být zmršený HTTP požadavek. K řeči přišla černá magie v podobě TCP dumpu na portu backednového serveru. Na první i druhý a dokonce třetí pohled se mi zdálo vše v pořádku. Nakonec jsme objevili, že požadavek obsahuje HTTP hlavičku Content-length s hodnotou 9 bajtů, ale požadavek už neobsahoval vlastní tělo. Příčina čekání bylo tedy v tom, že backend server čekal na tělo požadavku, které nikdy nedorazilo. Stále ovšem zbývalo vyřešit, kde k poškození požadavku dojde.

Nejdříve jsme podezřívali prohlížeč, u Internet Exploreru je ostražitost vždy na míste, ale ten posílal požadavek včetně jeho těla. Další na řadě byl load balancer atd. Nakonec se zdálo, že tělo požadavku zahodí frontend server resp. HTTP klient uvnitř, který požadavek přeposílal. Což mě logicky přivedlo k otázce, proč to HTTP klient dělá. Stávalo se to totiž jenom pro jeden konkrétní požadavek v konkrétním prohlížeči a v konkrétní verzi. Nakonec jsem skončil u kódu, který kopíroval HTTP požadavek. V něm vše vypadalo v pořádku až na jeden drobný detail.

//Vytvoreni HTTP metody
HttpMethodBase method;
if ("GET".equals(request.getMethod())) {
    method = new GetMethod(uri);
} else if ("POST".equals(request.getMethod())) {
    method = new PostMethod(uri);
    setRequestBody((PostMethod) method, request);
} else if ("PUT".equals(request.getMethod())) {
    method = new PutMethod(uri);
    setRequestBody((PutMethod) method, request);
} else if ("DELETE".equals(request.getMethod())) {
    method = new DeleteMethod(uri);
} else if ("HEAD".equals(request.getMethod())) {
    method = new HeadMethod(uri);
} else {
    ...
}

//Kopirovani HTTP hlavicek
for (Enumeration headerNames = request.getHeaderNames(); headerNames.hasMoreElements();) {
    method.setRequestHeader(headerName, request.getHeader(headerName));
}

Kód pro kopírování HTTP požadavku z abstrakce serveletu do abstrakce Apache Jakarta Commons HTTP client totiž kopíroval všechny HTTP hlavičky včetně Content-length, ale vlastní tělo požadavku se kopírovalo jenom pro POST metodu. Pak už to bylo jasné, protože abstrakce pro DELETE metodu nemá možnost nastavit tělo požadavku. Fix byl velice přímočarý, ignorovat originální Content-length hlavičku. Po něm vše začalo fungovat.

Shluky chyb

Na tomhle příběhu je pěkně ilustrovaná charakteristika chyb. Ty mají totiž tendenci se projevit pouze pokud se jich shlukne několik (mnohdy záleží i na pořadí). Zřídkakdy způsobí kolaps jedna jediná chyba, vždycky to musí být shluk několika chyb. Málokdy ten chlápek, co vám vytrhne server ze zásuvky, má v té serverovně oprávnění něco dělat. Velmi podobné je to i v reálném světě, pokud jste někdy sledovali například dokumenty na téma leteckých katastrof a nebo slyšeli o Černobylská havárii. Nikdy za tím nebyla jedna jediná chyba, ale jejich shluk.

Pokud se vrátíme k našemu příkladu, pak při podrobné analýze přijdeme na to, že při vynechání jakékoliv chyby, by nedošlo k takovému zřetězení, které by ve výsledku způsobilo to minutové čekání. Jinými slovy každá jedna izolovaná chyba by se neprojevila takto fatálně. A naopak pouze určitý shluk chyb vede k určitému selhání. Když to vezmeme na tomto konkrétním shluku.

    Vágní specifikace
    HTTP specifikace nikde explicitně neříká, že by DELETE metoda nemohla nebo nesměla poslat tělo požadavku. Je tedy na libovůli daného HTTP klienta, jak se k tomu postaví. Internet Explorer, u jiných prohlížečů jsem to nezkoumal, si specifikaci vykládá benevolentním způsobem. Zcela jinak si to ovšem vykládá použitý HTTP klient.
    Chyba klientské části aplikaci
    Při podrobném zkoumání se ukázalo, že obsah těla HTTP požadavku, poslaný prohlížečem, je pouze řetězec undefined. Čili to vypadá na klientskou chybu v JavaScript kódu aplikace, která se projeví pouze v Internet Exploreru.
    Chyba v serverové části aplikace
    Pokud by se hlavičky ve výše uvedeném kódu kopírovaly správně, opět by k problému nedošlo. Ale k projevení špatného kopírování dojde jenom pokud dojde k chybě předchozí a navíc server nebude Content-length hlavičku ignorovat pro DELETE mtodu.

Chyby které se projeví pouze ve shluku je velmi složité odhalit. V případě testů musíte mít velmi dobré pokrytí integračními testy, protože jednotkové testy vycházejí z vašich předpokladů, jak se bude chovat okolí testovaného subjektu, ať již ve vztahu ke vstupu a nebo výstupu. Pravděpodobnost, že tam dojde ke shluku, je velmi malá. Právě ve shluku a jeho unikátnosti je skrytá nebezpečnost těchto chyb.