NestJS naplózás, ami tényleg elmondja, mi történt

Miért nem elég a sima konzol kimenet?

A NestJS gyárilag hoz egy saját Logger nevű eszközt, és egy hétvégi projekthez ez tökéletesen megfelel. Olvasható sorokat ír ki, megjelöli, melyik osztály küldte az adott sort, és nulla beállítást igényel. A gond ott kezdődik, amikor egyszerre több kérést szolgálsz ki. Öt párhuzamos kérésből származó egyszerű szöveges sorok összekeverednek a terminálban, és semmi nem mondja meg, melyik sor melyik kéréshez tartozik. Nem lehet könnyen keresni bennük. Nem lehet elküldeni őket olyan helyre, ami strukturált adatot vár. Minden egyes írás szinkron módon történik, ugyan azon a szálon, amelyik éppen a forgalmat szolgálja ki.

Ez nem igazán hiba. Egyszerűen csak nem arra való, hogy egy valódi szolgáltatást szolgáljon ki.

Miért nem elég a sima konzol kimenet?

A szolgáltatás a beépített logger helyett a nestjs-pino csomagot használja, ami a pino könyvtárat köti be a Nestbe: egyszerre alkalmazásszintű loggerként és minden bejövő kérést feldolgozó rétegként is. A beállítás az app.module.ts fájlban él, nagyjából így:

Kép 1: nestjs-pino konfiguráció

Két sor számít igazán.

• A genReqId minden bejövő kérésnek ad egy saját azonosítót, és minden egyes naplósor, amit a kérés kiszolgálása közben írunk, (függetlenül attól, melyik szolgáltatás írta) automatikusan ugyanazt az azonosítót kapja.
• A redact kiszedi az olyan mezőket, mint a hitelesítési fejléc, még mielőtt azok lemezre kerülnének.

Fejlesztés közben a log a pino-pretty csomagon megy keresztül, hogy olvasható maradjon. Éles környezetben viszont nyers JSON, készen arra, hogy bármi vagy bárki megtudja emészteni a logokat.

A hiba, amit szinte mindenki elkövet

Amint strukturáltak a naplóid, a következő kérdés az, hogy hol hívod meg ténylegesen a logger.error metódust. Szerintem a legtöbbünknek az első ösztön, hogy mindent try és catch blokkba csomagol, és rögtön ott naplózza, mielőtt újra dobná a hibát, mert ez felelősségteljesnek tűnik. Pontosan ez a rossz irány.

A demó alkalmazásnak van egy rendelés végpontja, ami meghív egy szolgáltatást, az meghív egy másikat, az pedig egy harmadikat, ami egy szimulált raktárral beszél. Ha mindegyik elkapja a hibát, naplózza, majd újra dobja, egyetlen sikertelen rendelés három vagy négy szinte azonos hiba követést termel a napló folyamban. A logok mennyiségéből önmagában nem lehet megállapítani, hogy egy hibát látsz vagy négyet, és hogy melyik sor magyarázza el ténylegesen, mi történt. A hibakeresés, nyomozássá válik.

A megoldás szándékosan unalmas. A hibák egyszerűen tovaterjednek. Sem az orders.service.ts, sem az inventory.service.ts nem naplóz semmit, amikor valami elromlik, egyszerűen hagyják hogy felbuborékozzon a hiba. Az egyetlen hely, ahol valaha is log íródik az az egyetlen szűrő, ami mindent elkap, mielőtt az HTTP válasszá alakulna:

Kép 2: AllExceptionsFilter class kód részlet

Ez a szűrő dönti el azt is, mennyire legyen hangos. Ha egy vásárló olyat rendel, ami nincs raktáron, az nem hiba, hanem egy valid válasz. Ezért is figyelmeztetésként loggoljuk, és senkit nem riasztunk miatta. Minden, ami nem szándékos volt, valódi hibaként kerül loggolásra, mert azt valószínűleg valakinek meg is kell vizsgálnia.

A rendszer összetartása három szolgáltatáson át

Az egyszeri loggolás azonban csak a válasz fele. Mire egy hiba eljutna a szűrőhöz, már elveszett melyik szolgáltatásból jött és milyen adatokkal dolgozott, hacsak nem viszi magával az információt a hibával együtt.

Itt bizonyítja az értékét a raktárkezelő szolgáltatás. Amikor nem tud készletet lefoglalni, nem csak egy általános hibát dob hanem becsomagolja, egy adott üzleti helyzetre szabott kivételbe, és megtartja az eredeti hibát mint annak okát:

Kép 3: Try/Catch block példa amely egy helyen kezeli az összes error-t

Kép 4: Kódrészlet a hibaláncolás kialakításáról

A Node már jó ideje natívan támogatja a hibák láncolását, és a pino valóban meg is érti azt. Ha egy olyan terméket kérsz, ami nem létezik a raktárban, az egyetlen log, amit a szűrő ír, végül így néz ki:

InventoryReservationFailedException: Could not reserve 1 unit(s) of "UNKNOWN-SKU"
    at InventoryService.reserve (...)
    at OrdersService.createOrder (...)
caused by: Error: Unknown SKU "UNKNOWN-SKU": warehouse system returned no record
    at WarehouseService.checkStock (...)

Egy log, egy teljes kép, egészen a pontos hívásig, ami három réteggel lejjebb hibázott. A termékkód és a mennyiség is saját, önálló mezőként kerül csatolásra, nem pedig egy üzenet szövegébe tömve. Ami apróságnak tűnik, egészen addig amíg valóban megpróbálod visszakeresni a logokban egy adott termék minden sikertelen foglalását.

Tudni, mi történt akkor is, ha semmi nem romlott el

Mindaz, amiről eddig szó volt, csak akkor lép működésbe, ha valami elromlik. A kérések többsége nem romlik el, mégis időnként tudni akarod, melyik handler futott le, és mennyi ideig tartott, anélkül hogy ez éles környezetben minden egyes kérésnél zajjá válna.

A projektben van erre egy önálló elfogó réteg, ami debug szinten naplóz info helyett, kifejezetten azért, hogy láthatatlan maradjon, amíg valóban nem kérünk több részletet:

Kép 5: Önálló elfogó réteg

Szándékosan egyszerű, és soha nem nyúl a hibákhoz. Ha itt is elkapnánk a hibákat, csak újra megteremtenénk azt a duplikált naplózási problémát, amit a szűrő már megoldott.

A hangerő feltekerése egyetlen kérésre, nem az egész flottára

Néha az info szintű logok nem elegendőek egy adott probléma megértéséhez, de az egész szolgáltatást debug szintre kapcsolni nem feltétlen jó döntés. Mind a költség, mind az utólag átnézendő zaj mennyisége miatt. A szolgáltatás lehetővé teszi, hogy egyetlen kérés kapcsolja be magának a debug szintű loggolást egy fejléc segítségével, amit egy olyan titkos érték ellenőriz, amit a kliens nem tud kitalálni:

Kép 6: debugLoggingMiddleware, request szintű debug kapcsolásához kódrészlet

• Jó tudni: Van egy fontos részlet, amire érdemes odafigyelni a különböző rétegek regisztrálásánál, és ami a kódból önmagában nem feltétlenül derül ki. A middleware-ek regisztrálásának sorrendje és módja itt különösen fontos. A Nest alkalmazás létrehozása után közvetlenül meghívott app.use esetén a middleware túl korán kerülhet regisztrálásra, még azelőtt, hogy a Nest a modulokon keresztül regisztrált rétegeket ténylegesen bekötné. Ez azért problémás, mert a Nest ezeket csak később, az alkalmazás tényleges indulásakor kezdi el kezelni. Ezért érdemes a middleware-t ugyanazon a módon regisztrálni, ahogy a nestjs-pino is regisztrálja a saját rétegét: a modul konfigurációs metódusán keresztül. Így a middleware-ek ugyanabban a folyamatban és kiszámítható sorrendben kerülnek bekötésre.

Log akkor is, amikor senki nem küldött Http requestet

Nem minden történik egy HTTP kérésen belül. Ez a szolgáltatás ütemezve egyezteti a készletét. Egy ütemezett feladatnak pedig nincs kérése, amihez hozzá lehetne kötni egy korrelációs azonosítót. A megoldás, hogy csinálunk egyet magunk:

Kép 7: Cronjob logging kódrészlet

Az adott futás minden logja ugyanazt a kitalált azonosítót viseli, ugyanúgy, ahogy egy kérésen belül minden log a kérés saját azonosítóját viseli. Ez ugyanannak az elvnek egy kisebb változata, csak kézzel készítve, nem automatikusan.

• Jó tudni: Van egy fontos részlet, amire érdemes odafigyelni az ütemezett feladatok hiba kezelésénél. Önmagában az, hogy egy feladat futása során hiba történik, még nem garantálja, hogy a hiba megfelelően naplózva és követhetően jelenik meg. Ahhoz, hogy strukturált és hasznos log keletkezzen, szükség van egy olyan hibakezelési rétegre, amely ténylegesen elkapja és naplózza a hibát.

Az ütemező könyvtár alapértelmezett működését érdemes külön is ismerni: ha egy feladat hibát dob, és azt semmi nem kapja el, a könyvtár egy egyszerű console.error hívással naplózza a hibát. Ebben nincs struktúra, feladatazonosító vagy olyan információ, ami segítene a kapcsolódó logok összekötésében.

Ezért saját ütemezett feladatok esetén érdemes külön gondoskodni a hibák megfelelő kezeléséről és strukturált naplózásáról. Ez egy olyan működési részlet, amelyet nem feltétlenül lehet a saját kódból megállapítani, ezért érdemes a használt könyvtár forráskódját vagy dokumentációját is ellenőrizni.

Összegzés

Ha mindezt egyetlen mondatba kellene sűrítenem, az az lenne, hogy a logok egy olyan jövőbeli önmagadnak készülnek, aki mindent elfelejtett a projektről.

• Strukturáld úgy a logokat, hogy egy gép is tudjon bennük keresni.
• Adj minden kérésnek egy azonosítót, hogy végig tudd követni a szolgáltatásokon át.
• A hibákat pontosan egyszer naplózd, egyetlen helyen, és annyi kontextust vigyél magával a hibával, hogy az az egyetlen log is elmondja a teljes történetet.

Minden más csak részlet.

Kérdésed van? Írj nekünk, és mi segítünk megtalálni a számodra optimális megoldásokat.