Virtlab:LoggingDebugging
Z VirtlabWiki
| Verze z 22:51, 30. 7. 2007 Gry72 (Diskuse | příspěvky) ← Předchozí porovnání |
Verze z 23:11, 30. 7. 2007 Gry72 (Diskuse | příspěvky) Následující porovnání → |
||
| Řádka 79: | Řádka 79: | ||
| Údaje, které potřebujeme ukládat: | Údaje, které potřebujeme ukládat: | ||
| * timestamp | * timestamp | ||
| + | * facility, debug level | ||
| * Jméno lokality generující komponenty | * Jméno lokality generující komponenty | ||
| - | * ID generující komponenty - facility - bude použito jméno programu příslušného serveru | + | * jméno programu příslušného serveru |
| * PID | * PID | ||
| * source file & line (v levelu DEBUG a ERROR) | * source file & line (v levelu DEBUG a ERROR) | ||
| - | * Partnerská lokalita - při komunikačních akcích, pro snadné GREPování chybových zpráv a zasílání informace správci přislušné lokality | + | * 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: |
| - | * Transaction ID (XID) | + | ** Partnerská lokalita - při komunikačních akcích, pro snadné GREPování chybových zpráv a zasílání informace správci přislušné lokality |
| - | * Vysvětlující text - jednořádkový, '''pro srozumitelnost potenciálním cizincům v angličtině''' | + | ** Transaction ID (XID) |
| + | |||
| Formát logovacích zpráv je částečně předurčen formátem používaných Syslogem. | 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 unifikované logovací funkce '''VLLOG()'''. | + | '''Timestamp''' a '''IP adresu/hostname zdroje''' zprávy dodá Syslogd, '''PID''' dodá systémová funkce vsyslog() volaná z unifikované logovací funkce '''VLLOG()'''. Facility se nastaví pro program jedenkrát z '''initLogging()'''. |
Verze z 23:11, 30. 7. 2007
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 a podle nastavených pravidel případně přeposílány emailem na správné zodpovědné správce. Logovací soubory 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 sheůů 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 jak ?) 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ě 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.
XXX FacilityID se vezme ze souboru vl-debug.h a nastavi se pro cely beh programu, takze se bude pouzivat jako default ve volanich syslog(), kde uz staci uvadet jen prioritu.
Momentálně jsou definovány tyto parametry:
- -DBGLOG-actions=xxx
- -DBGLOG-sitename=x
Úrovně logování
Úrovně logování (priority zpráv) částečně předurčeny formátem používaných 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 priorit Syslogu využíváme následující úrovně:
- 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_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_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é) - použití funkcí LOG_UNEXPECTED_SYS_ERROR, resp. LOG_UNEXPECTED_USR_ERROR. Text zprávy pak obsahuje jméno a řádek zdrojového kódu, kde chyba vznikla, a popisné hlášení chyby generované funkcí perror() na základě globální proměnné errno. Lze použít makro ; Pozor, nevolat mezitím jiné systémové volání, to by změnilo 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
Používané 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)
Formát logovacích zpráv
Údaje, které potřebujeme ukládat:
- timestamp
- facility, debug level
- Jméno lokality generující komponenty
- jméno programu příslušného serveru
- 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, pro snadné GREPování chybových zpráv a zasílání informace správci přislušné lokality
- Transaction ID (XID)
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 unifikované logovací funkce VLLOG(). Facility se nastaví pro program jedenkrát z initLogging().
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, následuje za identifikátorem DEBUGLEVEL 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 <<,>>, a 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 a funkci pro zalogování zprávy, viz dále.
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í ?).
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.
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).
Knihovní funkce pro logování 2
man logger man 3 syslog: void openlog(const char *ident, int option, int facility); openlog("msg-prepend-string",LOG_NDELAY|LOG_CONS|LOG_PID, int facility (LOG_USER)); void syslog(FACILITY | PRIORITY , const char *format, ...); man 3 setlogmask: int setlogmask(int mask); - bitovým součtem se určí úrovně, které se mají funkcí syslog() skutečně logovat
A process has a log priority mask that determines which calls to sys-
log(3) may be logged. All other calls will be ignored. Logging is
enabled for the priorities that have the corresponding bit set in mask.
The initial mask is such that logging is enabled for all priorities.
