Hogy miért is fontos a logolás egy alkalmazásban? Miért firkálja a sok adatot feleslegesen, megtöltve a drága háttértárat? Hát ezért...
A történet egy komplex szolgáltatás egyik microservicének új verziójával kezdődött.
A beszállító átadta a teljes szoftvercsomagot, melyben minden alkalmazás kapott új verziót. Ez szokványos volt, vártuk is hogy érkezzen, de itt még nem tudtuk, mi szabadul el a környezeteinken.
A tesztelés ment manuálisan, és automatával egyaránt. Jelezte is az automata - és a manuális tesztelő is - hogy bizony az egyik alkalmazás logolásával gond van.
Illetve hogy nincs... Mármint logolás.
Merthogy a log konkrétan üres volt, pedig az előző verzió még indulást, leállást, beérkező kérést, választ, mindent logolt, amit egy ilyen alkalmazástól elvárhatnánk, és amiből tudjuk, hogy él, dolgozik.
Élt, dolgozott, csak nem tájékoztatott minket.
Természetesen ez nem volt szimpatikus, így jeleztük is a beszállítónak, hogy ennek mi nem örülünk, bármennyire is helytakarékos, és a performancia is mérhetetlenül minimálisan növekedett emiatt.
Ettől függetlenül leteszteltük, működött, tette a dolgát, ahogy a többi alkalmazás is, dehát tökéletes szoftver nincs, így jeleztünk is pár hibát, amit javítani igyekeztek a másik oldalon, átadva nekünk a megbeszélt időre a megbeszélt szoftvert, a jelzett javításokkal.
Gondoltuk mi.
Az új, javított, már-már tökéletesnek mondható csomag frissen, ropogósan csücsült a telepítőcsomagban, alig vártuk a telepítést, melyet gyorsan el is végeztek, estünk is neki kapásból, néztük a szép logolást.
Valóban javították, ott volt minden, ami korábban is, induláskor minden paraméter, a logo ascii art, használt portok és paraméterek, minden, amire egy üzemeltető, és tesztelő, büszkén néz.
Beérkező kéréseket csodásan kiszolgálja, még megjegyzést is fűz hozzá a logba, ahogy arra szükség van, a ticketet boldogan zártuk, konstatálva, hogy csak kimaradhatott valami, amit visszaraktak.
Sose gondoltuk volna, hogy ekkorát tévedhetünk.
Az alkalmazás csodásan futott a környezeteken, a performancia tesztelés alatt is csak dolgozott és dolgozott, végül kikerült a pre prod környezetre.
Végre először találkozik a verzió olyan emberekkel, akik nem mi vagyunk, na ha valaminek ki kell jönnie, hát itt kijön.
A verzió szokatlanul könnyen felment a pre prodra, gond nélkül frissült, és minden úgy működött, ahogy azt az üzlet megálmodta, minden szolgáltatás működik, a régiek és az újak is. Konstatáltuk is, hogy ennyire könnyen még nem is sikerült verziót frissíteni, és nagy csodálattal és örömmel álltunk neki megtervezni az élesítést.
Élesíteni persze csak éjszaka, amikor az ügyfelek alszanak, mert akkor senkit nem zavarunk, ha a rendszer nem megy.
Be is mentünk éjfélre, mert aki legény nappal, az éjszaka telepít.
A telepítés röpke 8 órája úgy repült el, mint egy pillangó, mely a mázsás súly felett van, de a szárnyai csak egy szabvány lepke méreteivel büszkélkedhet - dacára a jó társaságnak, ha az ember elfárad, az elfogyasztott kávémennyiségtől függetlenül is picit rosszul érinti az említett ember lelki zen kertjét.
Picit lassan, de lement azért a telepítés, így uzsgyi haza, hiszen vár a pihe-puha ágy, és a csábító alvás.
Hazaérve persze az ember arra gondol, hogy ha már a holtponton átesett a taxis "vezetési" képességeinek hála, legalább reggelizik egyet, esetleg egy gyors zuhany is segíthet a jó kedven, így 11 óra magasságában bedől arccal lefelé az ágyba, hogy forgolódjon 1-2 órát, mielőtt elalszik.
És megszólal a vekker, melyet homályos tekintettel próbál az ember leállítani, amikor is konstatál két fontos dolgot:
1: világos van, csak nem aludt 24 órányit
2: nem is állított be ébresztőt...
Sajnos az éles üzemért felelős ember telefonált, hogy bizony a korábban említett szolgáltatás nem hajlandó működni, és ezt bizony az ügyfelek vették észre. Háááááááát ez bizony nagyon gáz, gyors pillantás az órára, bizony délután fél 2. Ez nem volt sok alvás, viszont legalább tudjuk, hogy kb mióta nem működik a szolgáltatás.
Csipatörölgetés közben laptop üzembehelyezés, bekapcsolás, bejelentkezés - a közös megbeszélésbe, és a rendszerbe egyaránt.
Miután sikerült megtalálni, hogy melyik füles az amelyikből a sok aggodalmas hang jön, ráadásul sikerült a megfelelő fülpárosra rárakni, addigra sikerült előkaparni a logokat is.
A korábban említett microservice az, melyről most szó van. Arról, ami eredetileg semmit nem logolt, de biztos csak valami apróságot kellett javítani, mert minden visszajött.
Nézzük a logot, ellenőrizgetjük, dehát a felügyeleti rendszer se jelezte hogy tele lenne ERROR-al, pedig ilyenkor az ember arra számít, hogy megnyitva a logot minimum egy aktív csatatér közepén találja magát az ember, mindenféle INFO ERROR és WARN között, beszédes infók mindenfelé.
Meglepődésünkre összevissza csak WARN szinten dobálta magának az alkalmazás az Internal Server Error hibákat, és semmi több infó.
Ekkora már lefőtt a szükséges barna nedű, melyet ilyen helyzetben minimum intravénásan töltené magába az egyszeri problémamegoldó, dehát most arra se idő, se felszerelés, se tudás, szóval ez most bizony szájon megy be.
Akkor legyen a lehetetlen, emeljük a loglevelt. Felkészülni, Vigyázz, kész, DEBUG!
A log konfigjának átírása után perceken belül életbe lép az új beállítás, és már ömlik is a sok információ a logba, szállnak a bitek, rohannak a sorok, jön is egy kérés, nagyszerű, van már mit analizálni.
Nézzük is, keressük a hibát, dehát semmi. Megvan a kérés beérkezése, ide nyúl, ott keres, ilyet csinál, és utána elutasítja a kérést a mágikus 500-al.
Tanácstalanul nézünk, hogy "Ez itt ez miez itt mi?".
Közben a beszállítót értesítettük, hogy ez így nem túl baráti legyen már olyan kedves küldeni pár embert gondolkodni, hátha többet aludtak, vagy jobban értenek hozzá mint mi. Sajnos a kevésnek bizonyuló logból ők se tudnak sok mindenre tippelni, így hát nem maradt más hátra, mint az elképzelhetetlen.
TRACE-re fel!
Ömlik az infó, másodpercenként többszáz, ha nem ezer feletti sorszám, ezigen, percenként üresjáratban 50 MB-nyi log keletkezik, ezzel óvatosan bánunk.
Szerencsére jött egy kérés, és meglepő módon ez is Internal Server Error lett, szóval van adat analizálni, neki is esünk. Nézzük, fürkésszük, vadásszuk a hibát, támaszkodva az egyetlen dologra amiről tudtuk hogy van, a tapasztalatunkra és frissességünkre. Jelezném, itt már este 7 körül jártunk.
Ekkor megpillantottuk azt, amit sosem akartunk látni. Ami a fejlesztő, tesztelő, üzemeltető rémálma: NullPointerException
A veszélyes rém, ami ha megjelenik, azt mindenki megemlegeti, akkora stack trace-el, ami a monitorra nem fér ki.
Legalábbis mindenhol máshol, mert itt csupán egy fél sort kapott a szerencsétlen, oda kellett elférnie.
Mondanom sem kell, ebből kiindulva sem a beszállító fejlesztői, sem mi nem jutottunk egyáltalán messzire, az egyetlen amire tudtunk alapozni, hogy közvetlen előtte mit csinált a rendszer.
A hibát végül megtaláltuk, javítottuk, ez egy másik történet része.
Az viszont, hogy a logolás ilyen minősíthetetlenül gyengére sikerült, rettentően megnövelte a hiba feltárását, a root cause megtalálását, és javítását.
D
- A hozzászóláshoz regisztráció és bejelentkezés szükséges