Virtlab:LoggingDebugging
Z VirtlabWiki
Logování a debugging
Pro odladění, sledování provozu a řešení incidentů celého distribuovaného systému virtuální laboratoře je nutný konzistentní systém ukládání informací o běhu na různých úrovních, které bude možné snadno automaticky vyhodnocovat a informovat příslušné správce o kritických nebo nestandardních stavech. Informace o běhu všech komponent (serverů) lokality budou shromažďovány na Syslog serveru dané lokality, kde budou vyhodnocovány vhodnými skripty nebo prostředky syslog démona či pomocí phpsyslogng a podle nastavených pravidel případně přeposílány emailem na správné zodpovědné správce. Logovací soubory/databáze syslog serverů všech lokalit budou zpřístupněny pro čtení správcům všech ostatních lokalit (patrně přes WWW).
Z důvodu snadné implementace návazných rozšiření bude použit Syslog Next Generation (Syslog-ng).
Jednotlivé servery systému budou zasílat debug informace na syslog jednotně pomocí k tomu účelu vytvořené univerzální logovací funkce (C), kterou budou formou knihovny přilinkovávat (PHP bude volat jako externí program nebo bude vytvořen ekvivalent v PHP). Funkce zformátuje hlášení dohodnutým způsobem a předá jej Syslog serveru lokality (démonu Syslog-ng), s ohledem na případné parametry nastavení logovacího režimu na příkazovém řádku (resp. konfiguračního souboru v případě PHP).
Parametry příkazového řádku související s debuggingem budou pro všechny servery sjednoceny (přilinkováním k tomu účelu vytvořené parsovací inicializační funkce v C).
V případě, že budou servery lokality distribuovány na více strojů, bude na každém z nich instalován proxy syslog démon, který bude nastaven tak, aby zprávy pouze přeposílal na hlavní Syslog démon lokality.
Pro záznam hlášení na Syslog ze shell skriptů lze použít systémového programu logger.
Sledování distribuovaných transakcí
Abychom mohli v log souborech dostopovat sekvenci souvisejících záznamů o akcích, které se provedly jako důsledek nějakého jednoho požadavku iniciovaného uživatelem (nebo i systémem, typicky od časovače), budeme v protokolech všech serverů označovat požadavky i odpovědi tzv. identifikátorem transakce (XID). Identifikátor transakce bude hodnota ve tvaru XID=value umístěná mezi volitelnými parametry v hlavičce všech požadavků, resp. odpovědi na požadavky. Hodnotu identifikátoru transakce vymyslí jednoznačně iniciátor transakce (obvykle WWW aplikace) a ostatní servery ji budou pouze vracet v odpovědích, resp. kopírovat do požadavků, které vytvoří jako reakci na příchozí požadavek s daným XID. A samozřejmě také logovat do log souborů. XID bude řetězec, způsob vytváření bude sjednocen takto:
název_lokality.konstanta_facility.unix_timestamp.
Unifikované nastavení chování logování
Úroveň debuggingu všechny serverů (mimo WWW aplikace - tam pomocí vhodného .inc souboru) lze určit pomocí jednotného systému parametrů předávaných z příkazové řádky. Parametry jsou koncipovány tak, aby mohly být zpracovány společnou inicializační funkcí přilinkovávanou ke každému serveru a následně automaticky odstraněny, aby neposouvaly pořadí a neovlivńovaly počet základních parametrů očekávaných programem. Jména jednotných parametrů nastavujících úroveň debuggingu začínají vždy řetězcem -DBGLOG a mají tvar -DBGLOGxxx, resp. -DBGLOGxxx=hodnota. Na jejich pořadí včetně případném promísení s "normálními" parametry programu nezáleži. Načtení a odstranění debug parametrů se provede pomocí inicializační funkce initLogging(facilityID,*argc,*argv[]) (vl-debug.c), která volá vždy jako první příkaz v main(), tj. ještě před pokusem o parsování parametrů příkazové řádky vlastního programu.
Momentálně jsou definovány tyto parametry:
- -DBGLOGsite=x - nastaveni jmena mistni lokality (jen pro ucely logovani). Implicitne se bere s /etc/sitename.
- -DBGLOGlevel=x - od kterého debug levelu se mají hlášení skutečně posílat na Syslog
Možná ješte doplníme -DBGLOG-actions=xxx blíže určující, jaké "typy" informací se maji ukladat v levelu debug (DB access, mezikomponentová komunikace, forking/exitting procesů, info o běhu algoritmů, ...) ???
Úrovně logování
Úrovně logování (priority hlášení) jsou částečně předurčeny logikou zavedenou Syslogem:
- LOG_EMERG (system is unusable)
- LOG_ALERT (action must be taken immediately)
- LOG_CRIT (critical conditions)
- LOG_ERR (error conditions)
- LOG_WARNING (warning conditions)
- LOG_NOTICE (normal, but significant, condition)
- LOG_INFO (informational message)
- LOG_DEBUG (debug-level message)
Z úrovní Syslogu využíváme následující úrovně:
- LOG_DEBUG - info o akcích a interakcích komponent systému a stavech algoritmů - podrobné (doplňující LOG_INFO], vč. parametrů, dump zpráv vyměňovaných mezi komponenty, výpis přijatých a odeslaných dat, forking & exiting dynamicky vytvářených podprocesů, info o databázových operacích (texty prováděných SQL příkazů).
- LOG_INFO - info o zásadních akcích a interakcích komponent systému a stavech algoritmů (došlé požadavky a reakce na ně, výsledky výpočtů, spouštění akcí od časovače), - jednořádkové
- LOG_NOTICE - info o komunikačních akcích - přijatá a navázaná spojení + chyby,
- LOG_WARNINGS - info o chybách, ze kterých se systém zotavil
- LOG_ERR - ignorované neočekávané chyby vrácené ze systémových. resp. uživatelských volání (neošetřené)- Generují se použitím pomocně vytvořených funkcí LOG_UNEXPECTED_SYS_ERROR, resp. LOG_UNEXPECTED_USR_ERROR(errcode). Text vygenerované zprávy pak bude obsahovat jméno a řádek zdrojového kódu, kde chyba vznikla, u funkce LOG_UNEXPECTED_SYS_ERROR popisné hlášení chyby generované funkcí perror() na základě globální proměnné errno a u funkce LOG_UNEXPECTED_USR_ERROR číslo chyby předané jako argument. Mezi voláním ošetřované funkce a voláním LOG_UNEXPECTED_SYS_ERROR nesmí být volána jiná systémové volání, která by změnila obsah errno.
- LOG_CRIT (critical conditions) - informace o výpadku některých komponent vyžadující okamžitý administrátorský zásah (výpadek části systému)
- LOG_ALERT - informace o stavech způsobených chybou v kódu vyžadující odstranění chyby přeprogramováním
Facilities určují v Syslogu zdroj, resp. v našem případě komponentu, která vygenerovala hlášení.
Používané (číselné) identifikátory facilities a synonyma použivaná pro jednotlivé facilities jsou v souboru vl-debug.h:
- FAC_WWWAPP (LOG_LOCAL0) - webová aplikace řídícího serveru lokality (GUI, mapovací algoritmus)
- FAC_RSVSRV (LOG_LOCAL0+1) - rezervační server
- FAC_CONSSRV (LOG_LOCAL0+2) - konzolový server
- FAC_CONFSRV (LOG_LOCAL0+3) - konfigurační server
- FAC_CONFACT (LOG_LOCAL0+4) - aktivátor konfigurací a konfigurační skripty vč. VLANStore
- FAC_TUNSRV (LOG_LOCAL0+5) - tunelovací server
- FAC_ERASESRV (LOG_LOCAL0+6) - mazací server
- Zbývá 9 dalších hodnot (celkem je 5b pro facility, LOG_LOCAL0 je 16)
Údaje, které potřebujeme ukládat
- timestamp
- facility, debug level
- Jméno lokality generující komponenty
- jméno programu příslušného serveru komponenty
- PID
- source file & line (v levelu DEBUG a ERROR)
- Vysvětlující text - jednořádkový, pro srozumitelnost potenciálním cizincům v angličtině. Text může mj. obsahovat tyto významné údaje:
- Partnerská lokalita - při komunikačních akcích, nutná možnost snadného vyhledání pro zasílání chybových zpráv a informace správci přislušné lokality
- Transaction ID (XID)
Formát logovacích zpráv
Formát logovacích zpráv je částečně předurčen formátem používaných Syslogem. Timestamp a IP adresu/hostname zdroje zprávy dodá Syslogd, PID dodá systémová funkce vsyslog() volaná z naší unifikované logovací funkce VLLOG(). Facility se nastaví pro program jedenkrát z initLogging() (hodnota se vezme ze souboru vl-debug.h a bude se používat jako default ve volanich VLLOG(), kde pak už stačí uvádět jen debug level).
Formát zpráv v souboru vytvářeném syslogd vypadá takto:
DATE TIME SOURCE-HOST PROGRAM-ID[PID]: MSGTEXT
PROGRAM-ID je tvořen složením jména lokality a názvu programu (spustitelného souboru), vzájemně oddělených #. V případě řídící webové aplikace se jako jméno programu použije řetězec "WWW" (později může být doplněno o další rozlišení části webové aplikace použitím různých suffixů). Jméno lokality se načte při inicializaci logovacího systému funkcí initLogging() ze souboru /etc/sitename; lze jej také (s vyšší prioritou) nastavit parametrem příkazového řádku -DBGLOGsite=jmeno.
Sjednocený formát popisných textů logovaných zpráv
Pro usnadnění strojového zpracování je formát popisných textů hlášení (MSGTEXT) sjednocen takto:
DEBUGLEVEL {[filename:line]} : Free-form English Message
kde DEBUGLEVEL={ EMERG | ALERT |CRIT | ERR | WARNING | NOTICE | INFO | DEBUG }
Je-li DEBUGLEVEL roven DEBUG nebo ERROR, následuje za identifikátorem DEBUGLEVEL odděleným mezerou jméno a řádek zdrojového souboru ve tvaru [filename:line].
Je zavedena konvence, že
- pokud hlášení informuje o dění v partnerské lokalitě, je její jméno uvozeno takto: >>SITENAME<<.
- pokud se uvádí XID (a nejedná-li se o dump protokolové zprávy, který se provádí bez modifikací), uvádí se ve tvaru [[XIDvalue]]
- sekvencím <<,>>,[[,]] se jinak v textu hlášení vyhýbáme
Lze také použít sekvenci %m, která uloží popisný text k poslední systémové chybě (viz man syslog).
Knihovní funkce pro logování
Abychom dosáhli jednotné a pro programátory bezpracné nastavení úrovně logování u každého programu, vytvořili jsme několik pomocných funkcí v C, které se ke každému serveru přilinkují (stačí staticky, mají pár set bytes). Jedná se o inicializační funkci, funkci pro zalogování zprávy, a funkci pro zalogování informací o neočekávané chybě.
U PHP kódu předpokládáme nastavení úrovně debugování ve vhodném .php souboru, který se pomocí include připojuje ke všem .php souborům (soubor s konstantami, soubor s autentizací ?).
Ošetření neočekávaných chyb
Přiznejme si, že není možné ošetřit úplně všechno (i když se budeme snažit). Nicméně bychom měli aspoň vědět o tom, že vyvstal problém tam, kde jsme jej nečekali a kde přesně do bylo. Pokud tedy nějaká systémová funkce vrací chybový kód, který nechceme dále rozlišovat, protože jeho vrácení prostě nepředpokládáme, budeme volat před použitím jakéhokoli dalšího systémového volání (aby se nepřepsala hodnota proměnné errno) funkci LOG_UNEXPECTED_SYS_ERROR() (viz vl-debug.c), která zaloguje kód a vysvětlující text chyby (strerror(errno)) spolu se jménem zdrojového kódu a číslem řádku, na kterém je volání LOG_UNEXPECTED_SYS_ERROR() umístěno. Obdobným způsobem ošetřujeme uživatelské funkce, které nenastavují errno, pouze s tím rozdílem, že použijeme funkci LOG_UNEXPECTED_USR_ERROR(errcode), jejímž parametrem je právě neočekávaný chybovž kód uživatelské funkce (tedy typický zápis bude LOG_UNEXPECTED_USR_ERROR(UserFunc(...)); ). Pokud je errcode, resp. předaný parametr 0, obě funkce nedělají nic.
Pomocná debug hlášení pro základní ladění (tracing)
Do informací zasílaných na Syslog nebudeme míchat debug hlášení pro základní ladění (trasování kódu programu, typicky posílané pomocí printf na stdout během ladění). Aby program neobsahoval množství těchto zapomenutých ladících printf(), zavedeme konvenci, že veškerá takováto hlášení budou vypisovány výhradně funkcí DBGPRINTF. Tu dokážeme snadno ve zdrojových kódech na základě názvu jednak snadno najít a případě odstranit, ale hlavně povolit či zakázat její efekt tím, že ji (pomoci #define ve vl-debug.h) budeme definovat jako funkci printf nebo nullprintf s prázdným tělem podle toho, zda je před připojením souboru vl-debug.h definován symbol DEBUG (při ladění musí být, #define VDEBUG).
Nastavení syslog démona - logovací soubory
/etc/syslog.conf:
facility.debuglevel path_to_logfile facility.debuglevel *hostname.to.forward
- Lze použít * na místě facility i debuglevel
- Rovnitko pred debuglevel rika, ze se tyka jen jedne urovne, jinak teto a vyssich.
Skripty/konfigurace syslog-ng pro přeposílání kritických zpráv administrátorům příslušných lokalit
Bude doplněno.
Konfigurace lokálních proxy syslog-ng pro přeposílání zpráv na hlavní syslog server lokality
Bude doplněno.
