10 tipů pro správné protokolování aplikací

náš nejnovější partner JCP, Tomasz Nurkiewicz, předložil řadu příspěvků popisujících základní principy správného protokolování aplikací. Považoval jsem je za docela zajímavé, proto jsem se rozhodl je agregovat do kompaktnějšího formátu a představit vám je. Zde jsou jeho návrhy na čisté a užitečné protokoly: (poznámka: Původní příspěvky byly mírně upraveny pro zlepšení čitelnosti)

1) použijte vhodné nástroje pro práci

zdá se, že mnoho programátorů zapomíná, jak důležité je protokolování chování aplikace a její aktuální aktivity. Když někdo dá:

log.info("Happy and carefree logging");

naštěstí někde v kódu si pravděpodobně neuvědomuje důležitost protokolů aplikací během údržby, ladění a identifikace poruch. Podceňování hodnoty dobrých protokolů je strašná chyba.

podle mého názoru, SLF4J je nejlepší protokolování API k dispozici, hlavně proto, že velký vzor substituce podporu:

log.debug("Found {} records matching filter: '{}'", records, filter); 

v Log4j byste museli použít:

log.debug("Found " + records + " records matching filter: '" + filter + "'");

to je nejen delší a méně čitelné, ale také neefektivní kvůli rozsáhlému používání zřetězení řetězců. SLF4J přidává pěknou funkci substituce {}. Také proto, že je zabráněno zřetězení řetězců a toString () není volán, pokud je protokolovací příkaz filtrován, již není potřeba isDebugEnabled (). Mimochodem, všimli jste si jednotlivých uvozovek kolem parametru řetězce filtru?

SLF4J je jen fasáda. Jako implementaci bych doporučil již inzerovaný rámec Logback namísto dobře zavedeného Log4J. má mnoho zajímavých funkcí a na rozdíl od Log4J je aktivně vyvíjen.

posledním doporučeným nástrojem je Perf4J. citovat jejich motto:

Perf4J je systém.currentTimeMillis () jako log4j je systém.mimo.println ()

Přidal jsem Perf4J k jedné existující aplikaci pod velkým zatížením a viděl jsem ji v akci v několika dalších. Správci i firemní uživatelé byli ohromeni pěknými grafy vytvořenými tímto jednoduchým nástrojem. Také jsme byli schopni objevit výkonnostní nedostatky v žádném okamžiku. Perf4J sám si zaslouží svůj vlastní článek, ale prozatím jen zkontrolujte jejich průvodce pro vývojáře.

dále si všimněte, že Ceki Gülcü (zakladatel projektů Log4J, SLF4J a Logback) navrhl jednoduchý přístup, jak se zbavit závislosti na protokolování commons (viz jeho komentář).

2) Nezapomeňte, že úrovně protokolování jsou pro vás

pokaždé, když provedete protokolování, si myslíte, která úroveň protokolování je vhodná pro tento typ události, že? Nějak 90% programátorů nikdy nevěnuje pozornost úrovním protokolování, jednoduše zaznamenává vše na stejné úrovni, obvykle informace nebo ladění. Proč? Logovací rámce mají oproti systému dvě hlavní výhody.mimo., tj. kategorie a úrovně. Oba umožňují selektivně filtrovat příkazy protokolování trvale nebo pouze po dobu diagnostiky. Pokud opravdu nevidíte rozdíl, vytiskněte tuto tabulku a podívejte se na ni pokaždé, když začnete psát “ protokol.“ve vašem IDE:

chyba-stalo se něco strašně špatného, které musí být okamžitě vyšetřeno. Žádný systém nemůže tolerovat položky přihlášené na této úrovni. Příklad: NPE, databáze není k dispozici, kritický případ použití nelze pokračovat.

varujte-proces může pokračovat, ale buďte opatrní. Vlastně jsem tu vždycky chtěl mít dvě úrovně: jednu pro zjevné problémy, kde existuje obcházení (například: „Aktuální data nejsou k dispozici, pomocí hodnot uložených v mezipaměti“) a za druhé (pojmenujte to: pozor) pro potenciální problémy a návrhy. Příklad: „aplikace běžící ve vývojovém režimu „nebo“ administrační konzola není zabezpečena heslem“. Aplikace může tolerovat varovné zprávy, ale měly by být vždy odůvodněny a prozkoumány.

INFO-důležitý obchodní proces byl dokončen. V ideálním světě by měl být administrátor nebo pokročilý uživatel schopen porozumět informačním zprávám a rychle zjistit, co aplikace dělá. Například pokud je aplikace o rezervaci letenek, na každou letenku by mělo být pouze jedno informační prohlášení s nápisem „rezervovaná letenka od do“. Další definice informační zprávy: Každá akce, která výrazně změní stav aplikace (aktualizace databáze, externí požadavek na systém).

DEBUG-vývojáři věci. Budu diskutovat později, jaký druh informací si zaslouží být zaznamenán.

TRACE-velmi podrobné informace, určené pouze pro vývoj. Po nasazení do produkčního prostředí můžete zprávy trasovat po krátkou dobu, ale považujte tyto příkazy protokolu za dočasné, které by měly nebo mohly být nakonec vypnuty. Rozdíl mezi laděním a trasováním je nejobtížnější, ale pokud vložíte protokolování a odstraníte jej poté, co byla funkce vyvinuta a testována, měla by být pravděpodobně na úrovni trasování.

výše uvedený seznam je jen návrh, můžete si vytvořit vlastní sadu pokynů, které je třeba dodržovat,ale je důležité mít nějaké. Moje zkušenost je, že vždy je vše zaznamenáno bez filtrování (alespoň z kódu aplikace), ale schopnost rychle filtrovat protokoly a extrahovat informace se správnou úrovní podrobností může být zachráncem života.

poslední věc, která stojí za zmínku, je neslavná podmínka is * Enabled (). Někteří to dali před každé prohlášení o protokolování:

if(log.isDebugEnabled()) log.debug("Place for your commercial");

osobně, zjistil jsem, že tento idiom je jen nepořádek, kterému je třeba se vyhnout. Zlepšení výkonu (zejména při použití substituce vzoru SLF4J diskutované dříve) se zdá irelevantní a voní jako předčasná optimalizace. Taky, můžete si všimnout duplikace? Existují velmi vzácné případy, kdy je explicitní podmínka oprávněná-když dokážeme, že vytváření protokolovací zprávy je drahé. V jiných situacích, jen dělat svou práci protokolování a nechat protokolování framework dělat svou práci (filtrování).

3) víte, co se přihlašujete?

pokaždé, když vydáte protokolovací příkaz, udělejte si chvilku a podívejte se, co přesně přistane ve vašem souboru protokolu. Přečtěte si své protokoly později a na místě vadné věty. Nejdříve, vyhněte se takovým NPEs:

log.debug("Processing request with id: {}", request.getId());

jste si naprosto jisti, že požadavek zde není nulový?

dalším úskalím je protokolování sbírek. Pokud jste načetli sbírku doménových objektů z databáze pomocí hibernace a neopatrně je zaznamenáte jako zde:

log.debug("Returning users: {}", users);

SLF4J zavolá toString () pouze tehdy, když je příkaz skutečně vytištěn, což je docela pěkné. Ale pokud ano … z chyby paměti, N + 1 Vyberte problém, hladovění vlákna (protokolování je synchronní!), líná inicializace výjimka, logy skladování zcela vyplněna-každý z nich může dojít.

je mnohem lepší logovat například pouze ID doménových objektů (nebo dokonce pouze velikost sbírky). Ale dělat sbírku ID, když má sbírku objektů, které mají metodu getId (), je v Javě neuvěřitelně obtížné a těžkopádné. Groovy má skvělý operátor šíření (users*. id), v Javě jej můžeme napodobit pomocí knihovny Commons Beanutils:

log.debug("Returning user ids: {}", collect(users, "id"));

kde metoda collect () může být implementována následovně:

public static Collection collect(Collection collection, String propertyName) { return CollectionUtils.collect(collection, new BeanToPropertyValueTransformer(propertyName));}

poslední věc, kterou je třeba zmínit, je nesprávná implementace nebo použití toString(). Nejprve vytvořte toString() pro každou třídu, která se objeví kdekoli v protokolech protokolování, nejlépe pomocí ToStringBuilder(ale ne jeho reflexní protějšek). Za druhé, dejte si pozor na pole a netypické sbírky. Pole a některé podivné sbírky nemusí mít toString () implementované volání toString () každé položky. Použijte metodu nástroje pole #deepToString JDK. A číst protokoly často na místě nesprávně formátované zprávy.

4) Vyhněte se nežádoucím účinkům

protokolování by nemělo mít žádný nebo malý dopad na chování aplikace. Nedávno můj přítel dal příklad systému, který hodil hibernace ‚ LazyInitializationException pouze při spuštění na nějakém konkrétním prostředí. Jak jste pravděpodobně uhodli z kontextu, některé logovací příkazy způsobily, že při připojení relace byla načtena líná inicializovaná kolekce. V tomto prostředí byly úrovně protokolování zvýšeny a sběr již nebyl inicializován. Přemýšlejte, jak dlouho by vám trvalo najít chybu, aniž byste znali tento kontext?

dalším vedlejším účinkem je zpomalení aplikace. Rychlá odpověď: pokud se přihlásíte příliš mnoho nebo nesprávně používáte toString () a/nebo zřetězení řetězců, protokolování má vedlejší účinek na výkon. Jak velký? Viděl jsem restartování serveru každých 15 minut kvůli hladovění vlákna způsobenému nadměrným protokolováním. Nyní je to vedlejší účinek! Z mé zkušenosti je několik stovek MiB pravděpodobně horní hranicí toho, kolik se můžete přihlásit na disk za hodinu.

samozřejmě, pokud protokolování prohlášení sám selže a způsobí, že obchodní proces ukončit kvůli výjimce, to je také obrovský vedlejší efekt. Viděl jsem takový konstrukt, abych se tomu vyhnul:

try { log.trace("Id=" + request.getUser().getId() + " accesses " + manager.getPage().getUrl().toString())} catch(NullPointerException e) {}

Toto je skutečný kód, ale prosím, udělejte svět trochu lepším místem a nedělejte to, nikdy.

5) být stručné a popisné

každý protokolovací příkaz by měl obsahovat data i popis. Zvažte následující příklady:

log.debug("Message processed");log.debug(message.getJMSMessageID());log.debug("Message with id '{}' processed", message.getJMSMessageID());

který protokol byste chtěli vidět při diagnostice selhání v neznámé aplikaci? Věřte mi, všechny výše uvedené příklady jsou téměř stejně běžné. Další anti-vzor:

if(message instanceof TextMessage) //...else log.warn("Unknown message type");

bylo tak těžké zahrnout skutečný typ zprávy, ID zprávy, atd. ve varovném řetězci? Vím, že se něco pokazilo, ale co? Jaký byl kontext?

třetí anti-vzor je „magic-log“. Příklad skutečného života: většina programátorů v týmu věděla, že 3 ampersands následovaný vykřičníkem, následovaný hash, následovaný pseudonáhodným alfanumerickým řetězcovým logem znamená „zpráva s přijatým XYZ id“. Nikdo se neobtěžoval změnit protokol, prostě někdo narazil na klávesnici a vybral si nějaký jedinečný „&&&!# „řetězec, takže jej lze snadno najít sám.

v důsledku toho celý soubor logů vypadá jako náhodná posloupnost znaků. Někdo by mohl dokonce považovat tento soubor za platný program Perl. Místo toho by měl být soubor protokolu čitelný, čistý a popisný. Nepoužívejte magická čísla, hodnoty protokolu, čísla, ID a nezahrnujte jejich kontext. Zobrazte zpracovávaná data a ukažte jejich význam. Ukažte, co program skutečně dělá. Dobré protokoly mohou sloužit jako skvělá dokumentace samotného kódu aplikace.

zmínil jsem se, že nemám zaznamenávat hesla a žádné osobní údaje? Nedělej to!

6) Nalaďte si vzor

protokolování vzor je skvělý nástroj, který transparentně přidává smysluplný kontext každé protokolování prohlášení, které provedete. Musíte však velmi pečlivě zvážit, které informace zahrnout do svého vzoru. Například datum protokolování, když se vaše protokoly každou hodinu valí, je zbytečné, protože datum je již zahrnuto v názvu souboru protokolu. Naopak, bez přihlášení názvu vlákna byste nemohli sledovat jakýkoli proces pomocí protokolů, když dvě vlákna pracují současně – protokoly se překrývají. To by mohlo být v pořádku v jednovláknových aplikacích-které jsou dnes téměř mrtvé.

z mé zkušenosti by ideální protokolovací vzor měl zahrnovat (samozřejmě kromě samotné přihlášené zprávy): aktuální čas (bez data, milisekundová přesnost), úroveň protokolování, název vlákna, jednoduchý název loggeru (není plně kvalifikovaný) a zpráva. V Logbacku je to něco jako:

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <encoder> <pattern>%d{HH:mm:ss.SSS} %-5level %m%n</pattern> </encoder></appender>

nikdy byste neměli obsahovat název souboru, název třídy a číslo řádku, i když je to velmi lákavé. Dokonce jsem viděl prázdné příkazy protokolu vydané z kódu:

log.info("");

protože programátor předpokládal, že číslo řádku bude součástí logovacího vzoru a věděl, že „pokud se v 67. řádku souboru (v metodě authenticate() objeví prázdná logovací zpráva), znamená to, že uživatel je ověřen“. Kromě toho má logování názvu třídy, názvu metody a / nebo čísla řádku vážný dopad na výkon.

poněkud pokročilejší funkcí logovacích rámců je koncept mapovaného diagnostického kontextu. MDC je jednoduše mapa spravovaná na místní bázi. Do této mapy můžete vložit libovolný pár klíč-hodnota a od té doby bude mít každý protokolovací příkaz vydaný z tohoto vlákna tuto hodnotu připojenou jako součást vzoru.

7) argumenty metody protokolu a návratové hodnoty

když během vývoje najdete chybu, obvykle spustíte debugger, který se snaží vystopovat potenciální příčinu. Nyní si na chvíli představte, že nemůžete použít debugger. Například proto, že se chyba projevila v Zákaznickém prostředí před několika dny a vše, co máte, jsou protokoly. Našli byste v nich něco?

pokud se budete řídit jednoduchým pravidlem protokolování jednotlivých vstupů a výstupů metody (argumenty a návratové hodnoty), už nepotřebujete ani debugger. Samozřejmě musíte být rozumní, ale každá metoda, která: přistupuje k externímu systému (včetně databáze), bloky, čeká atd. mělo by být zváženo. Jednoduše postupujte podle tohoto vzoru:

public String printDocument(Document doc, Mode mode) { log.debug("Entering printDocument(doc={}, mode={})", doc, mode); String id = //Lengthy printing operation log.debug("Leaving printDocument(): {}", id); return id;}

protože zaznamenáváte začátek i konec vyvolání metody, můžete ručně objevit neefektivní kód a dokonce odhalit možné příčiny zablokování a hladovění-jednoduše tím, že se postaráte o“ zadání „bez odpovídajícího „opuštění“. Pokud vaše metody mají smysluplná jména, čtení protokolů by bylo potěšením. Také analýza toho, co se pokazilo, je mnohem jednodušší, protože na každém kroku přesně víte, co bylo zpracováno. Můžete dokonce použít jednoduchý aspekt AOP k přihlášení široké škály metod ve vašem kódu. To snižuje duplikaci kódu, ale buďte opatrní, protože to může vést k obrovskému množství obrovských protokolů.

měli byste zvážit úrovně ladění nebo trasování jako nejvhodnější pro tyto typy protokolů. A pokud zjistíte, že některé metody jsou volány příliš často a protokolování by mohlo poškodit výkon, jednoduše snížit úroveň protokolování pro tuto třídu nebo zcela odstranit protokol (možná ponechat jen jeden pro celou metodu vyvolání?) Ale vždy je lepší mít příliš mnoho než příliš málo logovacích příkazů. S příkazy protokolování zacházejte se stejným respektem jako s jednotkovými testy – váš kód by měl být pokryt rutinami protokolování, jako je tomu u jednotkových testů. Žádná část systému by neměla zůstat bez protokolů. Nezapomeňte, že někdy pozorování protokolů, které se pohybují, je jediný způsob, jak zjistit, zda vaše aplikace funguje správně nebo visí navždy.

8) pozor na externí systémy

Toto je zvláštní případ předchozího tipu: pokud komunikujete s externím systémem, zvažte přihlášení každého kusu dat, který vychází z vaší aplikace a dostane se dovnitř. Období. Integrace je těžká práce a diagnostika problémů mezi dvěma aplikacemi (myslete na dva různé dodavatele, prostředí, technologické zásobníky a týmy) je obzvláště obtížná. Nedávno jsme například zjistili, že protokolování plného obsahu zpráv, včetně hlaviček SOAP a HTTP ve webových službách Apache CXF, je velmi užitečné při integraci a testování systému.

Jedná se o velkou režii a pokud je problém s výkonem, můžete protokolování vždy zakázat. Ale jaký má smysl mít rychlou, ale zlomenou aplikaci, kterou nikdo nemůže opravit? Při integraci s externími systémy buďte zvlášť opatrní a připravte se na zaplacení těchto nákladů. Pokud budete mít štěstí a veškerá vaše integrace je zpracována ESB, pak je sběrnice pravděpodobně nejlepším místem pro přihlášení všech příchozích požadavků a odpovědí. Viz například mezky ‚ log-component.

někdy je množství informací vyměňovaných s externími systémy nepřijatelné zaznamenávat vše. Na druhou stranu během testování a na krátkou dobu při výrobě (například když se děje něco špatného) bychom chtěli mít vše uloženo v protokolech a jsme připraveni zaplatit náklady na výkon. Toho lze dosáhnout pečlivým použitím úrovní protokolování. Stačí se podívat na následující idiom:

Collection<Integer> requestIds = //...if(log.isDebugEnabled()) log.debug("Processing ids: {}", requestIds);else log.info("Processing ids size: {}", requestIds.size());

pokud je tento konkrétní logger nakonfigurován pro protokolování ladicích zpráv, vytiskne celý obsah kolekce requestIds. Pokud je však nakonfigurován pro tisk informačních zpráv, bude vyvedena pouze velikost kolekce. Pokud vás zajímá, proč jsem zapomněl na isInfoEnabled () stav, vraťte se na tip #2. Jedna věc, která stojí za zmínku, je, že kolekce requestIds by v tomto případě neměla být nulová. I když to bude zaznamenán správně jako null, pokud je povoleno ladění, ale big fat NullPointerException bude vyvolána, pokud je logger nakonfigurován tak, aby informace. Vzpomeňte si na mou lekci o vedlejších účincích v tip #4?

9) log výjimky správně

nejprve se vyhněte protokolování výjimek, nechte svůj rámec nebo kontejner (ať už je to cokoli) udělat za vás. Existuje jedna, ekhem, výjimka z tohoto pravidla: pokud hodíte výjimky z nějaké vzdálené služby (RMI, EJB remote session bean atd.), který je schopen serializovat výjimky, ujistěte se, že jsou všechny dostupné klientovi (jsou součástí API). V opačném případě klient obdrží NoClassDefFoundError: SomeFancyException namísto chyby „true“.

výjimky protokolování jsou jednou z nejdůležitějších rolí protokolování vůbec, ale mnoho programátorů má tendenci považovat protokolování za způsob, jak zvládnout výjimku. Někdy vrátí výchozí hodnotu (obvykle null, 0 nebo prázdný řetězec) a předstírají, že se nic nestalo. Jindy výjimku nejprve zaznamenají a pak ji zabalí a hodí zpět:

log.error("IO exception", e);throw new MyCustomException(e);

tento konstrukt téměř vždy vytiskne stejnou stopu zásobníku dvakrát, protože něco nakonec zachytí MyCustomException a zaznamená jeho příčinu. Log, nebo zabalit a hodit zpět (což je vhodnější), nikdy obojí, jinak vaše protokoly budou matoucí.

ale pokud opravdu chceme zaznamenat výjimku? Z nějakého důvodu (protože nečteme API a dokumentaci?), asi polovina logovacích příkazů, které vidím, je špatná. Rychlý kvíz, který z následujících příkazů protokolu bude správně zaznamenávat NPE?

try { Integer x = null; ++x;} catch (Exception e) { log.error(e); //A log.error(e, e); //B log.error("" + e); //C log.error(e.toString()); //D log.error(e.getMessage()); //E log.error(null, e); //F log.error("", e); //G log.error("{}", e); //H log.error("{}", e.getMessage()); //I log.error("Error reading configuration file: " + e); //J log.error("Error reading configuration file: " + e.getMessage()); //K log.error("Error reading configuration file", e); //L}

překvapivě jsou správné pouze G a nejlépe L! A A B ani kompilují v SLF4J, jiní zahodí stopy zásobníku a / nebo vytisknou nesprávné zprávy. Například E nic nevytiskne, protože NPE obvykle neposkytuje žádnou výjimku a stopa zásobníku se také nevytiskne. Nezapomeňte, že prvním argumentem je vždy textová zpráva, napište něco o povaze problému. Nezahrnujte zprávu o výjimce, protože se automaticky vytiskne za příkazem protokolu, který předchází trasování zásobníku. Abyste to však mohli udělat, musíte jako druhý argument předat samotnou výjimku.

10) protokoly snadno čitelné a snadno analyzovatelné

existují dvě skupiny přijímačů, které se zvláště zajímají o vaše protokoly aplikací: lidské bytosti (možná nesouhlasíte, ale programátoři patří také do této skupiny) a počítače (obvykle shell skripty napsané správci systému). Protokoly by měly být vhodné pro obě tyto skupiny. Pokud se někdo dívá zezadu na vaše protokoly aplikací (zdroj Wikipedia):

pak jste pravděpodobně nesledovali mé tipy. Protokoly by měly být čitelné a snadno pochopitelné, stejně jako kód by měl.

na druhou stranu, pokud vaše aplikace produkuje půl GB protokolů každou hodinu, žádný člověk a žádný grafický textový editor je nikdy nedokáže přečíst úplně. Zde se hodí old-school grep, sed a awk. Pokud je to možné, zkuste protokolovací zprávy psát tak, aby jim rozuměli jak lidé, tak počítače, např. vyhněte se formátování čísel, použijte vzory, které lze snadno rozpoznat regulárními výrazy atd. Pokud to není možné, vytiskněte data ve dvou formátech:

log.debug("Request TTL set to: {} ({})", new Date(ttl), ttl);// Request TTL set to: Wed Apr 28 20:14:12 CEST 2010 (1272478452437)final String duration = DurationFormatUtils.formatDurationWords(durationMillis, true, true);log.info("Importing took: {}ms ({})", durationMillis, duration);//Importing took: 123456789ms (1 day 10 hours 17 minutes 36 seconds)

počítače ocení časový formát „ms after 1970 epoch“, zatímco lidé by byli potěšeni, když vidí text“ 1 den 10 hodin 17 minut 36 sekund“. BTW podívejte se na DurationFormatUtils, pěkný nástroj.

to jsou všichni kluci, „extravagantní tipy pro protokolování“ od našeho partnera JCP, Tomasze Nurkiewicze. Nezapomeňte se podělit!

Související Články :
  • protokolování Antipatterns
  • věci každý programátor by měl vědět
  • zákony návrhu softwaru
  • Java Best Practices – Vector vs ArrayList vs HashSet
  • Java Best Practices – DateFormat v Multithreading prostředí
  • Java Best Practices – High performance Serialization
  • Java Best Practices – String performance A Exact String Matching
související úryvky :
  • vytvořit vlastní Formátovač pro logger handler
  • volání metody protokolu
  • nastavit filtr na logger handler
  • nastavit Formátovač pro logger handler
  • protokolování aspekt příklad
  • Log4j Maven příklad
  • hibernace konfigurace protokolování-SLF4J + Log4j a Logback