Virtlab:LoggingDebugging

Z VirtlabWiki

(Rozdíly mezi verzemi)

Verze z 04:37, 1. 11. 2007

Obsah

1 Logování a debugging

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.

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 (nebo např. XID:value podle požadavků příslušného protokolu) 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.UserID.unix_timestamp.

Je-li akce inicována systémovou komponentou, např. od časovače, místo jména uživatele bude řetězec #SYS#.

Unifikované nastavení chování logování

Úroveň debuggingu všech 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(argc*,argv,facilityID) (vl-debug.c), která se 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. FacilityID viz vldebug.h.

Momentálně jsou definovány tyto parametry:

-DBGLOGsite=x - nastaveni jmena mistni lokality (jen pro ucely logovani). Implicitne se bere s /etc/sitename.
-DBGLOGlevel={EMERG|ALERT|CRIT|ERR|WARNING|NOTICE|INFO|DEBUG} - od kterého debug levelu se mají hlášení skutečně posílat na Syslog. Pokud není explicitně nastaveno, použije se LOG_CRIT.

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_WARNING - 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). Taktéž problémy se startem komponent způsobené špatnou konfigurací.
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 a mazače konfigurací laboratorních prvků
FAC_TUNSRV (LOG_LOCAL0+5) - tunelovací server
FAC_ERASESRV (LOG_LOCAL0+6) - mazací server
FAC_ACTSRV (LOG_LOCAL0+7) - aktivační server
Zbývá 8 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 }

Uživatel do funkce VLLOG() zadává pouze Free-form-English-Message, zbytek generuje funkce VLLOG().

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ě.

Hlavičky všech funkcí jsou ve vl-debug.h, těla v vl-debug.c. V souboru vl-debug-test.c je příklad použití všech možností debug/log systému.

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

(Syslog) /etc/syslog.conf:

facility.debuglevel    path_to_logfile
facility.debuglevel    *hostname.to.forward

mail.err    /var/log/mail.err

Lze použít * na místě facility i debuglevel
Rovnitko pred debuglevel rika, ze se tyka jen jedne urovne, jinak teto a vyssich.

(Syslog-ng) /etc/syslog-ng/syslog-ng.conf:

source s_all {
        # message generated by Syslog-NG
        internal();

        # standard Linux log source (this is the default place for the syslog() function to send logs to)
        unix-stream("/dev/log");

        # messages from the kernel
        file("/proc/kmsg" log_prefix("kernel: "));

        # use the following line if you want to receive remote UDP logging messages (this is equivalent to the "-r" syslogd flag)
        udp();
};

filter f_local0 { facility(local0); };

destination d_virtlab { file("/var/log/virtlab.log"); };

log {
        source(s_all);
        filter(f_local0);
        destination(d_virtlab);
};

source určuje zdroj syslog zprav
destination určuje, kam se mají zpravy ukládat
filter provede filtraci zprav podle zadaných parametrů

Spise nez logovat do ruznych souboru je treba logovat do mysql, a tam to "nejak" upravit( slozene informace rozlozit) a zobrazovat. Jak rozchodit syslog-ng aby logoval do mysql je popsano na http://gentoo-wiki.com/HOWTO_setup_PHP-Syslog-NG nebo na http://www.vermeer.org/display_doc.php?doc_id=1

Strucny navod logovani z syslog-ng do mysql

stahnout phpsyslogng z http://sourceforge.net/projects/php-syslog-ng/
nainstalovat, upravit soubor config.php
vytvorit db podle souboru dbsetup.sql
vytvorit pipe (pojmenovanou pipu/pajpu) mkfifo /var/log/mysql.pipe
upravit soubor /etc/syslog-ng/syslog-ng.conf : ukazka

 #syslog-ng conf file for use with phpsyslog-ng
 destination d_mysql { program("/usr/bin/mysql --user=syslogfeeder --password=PASSWORD syslog < /var/log/mysql.pipe"); pipe ("/var/log/mysql.pipe" template("INSERT INTO logs (host, facility, priority, level, tag, datetime, program, msg) VALUES ( '$HOST', '$FACILITY', '$PRIORITY', '$LEVEL', '$TAG', '$YEAR-$MONTH-$DAY $HOUR:$MIN:$SEC','$PROGRAM', '$MSG' );\n") template-escape(yes)); };
 source src { unix-stream("/dev/log"); pipe("/proc/kmsg"); udp(); tcp(); internal(); };
 log { source(src); destination(d_mysql); };

popis ukazky

prvni radek
urcuje kam se bude logovat, data se zapisou do pipe (pajpy/pipy) /var/log/mysql.pipe, uprav to podle sablony(jako sql insert), a spust program ktery zapise obsah pipy do mysql
druhy radek
urci odkud se budou brat logy
treti radek
urci co se ma kam logovat, je mozne pridat jeste filtr a tedy dulezite info posilat na mail/sms. Filtr se da psat jako regularni vyraz(vypocetne narocnejsi)

Nutno zabezpecit

bezici mysql server : uprava /etc/init.d/syslog-ng do start sekce pridat start mysql(pro jistotu)

Skripty/konfigurace syslog-ng pro přeposílání kritických zpráv administrátorům příslušných lokalit

staci upravit configuracni soubor syslog-ng. do logovaci sekce pridat filter

syslog-ng faq: http://www.campin.net/syslog-ng/faq.html; http://sial.org/howto/logging/syslog-ng/; CESKY http://www.abclinuxu.cz/blog/dw/2007/7/25/187781
ukazka konfiguraku: http://www.campin.net/syslog-ng.conf

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.

Logování v PHP skriptech

Pro logování a debug ve skriptech PHP je rovněž vytvořena sada funkcí. Jsou uloženy v souboru vl-debug.php.

Na začátku každého php skriptu, kde budeme využívat logování, načteme skript vl-debug.php.

K otestování návratové hodnoty uživatelské funkce pak použijeme funkci LOG_UNEXPECTED_USR_ERROR(navratova_hodnota,__LINE__); Narozdíl od stejnojmenné funkce v C, je zde nutné uvést číslo řádku - pomocí předdefinované konstanty __LINE__.

Jakákoliv chyba, která se ve skriptu vyskytne je automaticky odchycena a zpracována (uložena do logu) funkcí LOG_UNEXPECTED_SYS_ERROR. Tu tedy není nutné explicitně volat.

Pro logování různých úrovní "chyb" použijeme funkci VLLOG($uroven,__LINE__,"textova zprava"). Ta má oproti verzi v C ještě navíc parametr __LINE__.

Pro pomocná debug hlášení slouží DBGPRINTF($formatovaci_retezec,[$dalsi_argumenty,[....]]). Vyžaduje argumenty stejným způsobem jako např. funkce printf()

Debug výpis se dá vypnout/zapnout podle nastavení konstanty VDEBUG v souboru vl-debug-const.php. V tomto souboru se nastavuje také úroveň logování.

Příklad použití je v souboru vl-debug-test.php.

Logování ve shell skriptech

Pro záznam hlášení na Syslog ze shell skriptů používáme funkci VLLOG z COMMON/src/vl-debug.sh. Logováni musí být nejprve inicializováno funkcí INITLOGGING FAC_xxx (nastavení implicitní facility).

Syntaxe VLLOG je

VLLOG {emerg|alert|crit|err|info|notice|warning|debug } TEXT

V levelu debug se automaticky do zprávy zaloguje i jméno skriptu a aktuální řádek.

Pro realizaci se používá systémového programu logger.

Úrovně, které se mají pro jednotlivé facility logovat, jsou nastaveny v souboru /etc/virtlab/shell-logging.conf. Syntaxe viz příklad.

Příklad použití viz vl-debug-test.sh.

Není-li zavoláno INITLOGGING a promenna VGLLOG_FACILITY není nastavena (zděděna), nastavuje se na VLLOG_UNDEFINED a zprávy se logují s facility local8.

Ukladani zaznamu, ohlasovani chyb e-mailem

Od loggingu ocekavame toto:

Log hlaseni generovana komponentami urcite lokality by se mely automaticky zaznamenavat do souboru syslogu teto lokality. A to vcetne identifikace facility a debugLevelu
Log hlaseni generovana komponentami urcite lokality od urciteho nastaveneho debugLevelu vyse by se mely take kopirovat na emailovu adresu prirazenou lokalite pro "urgentni" zpravy. Ty se budou preposilat na SMS, takze by mely byt formatovany tak, aby clovek na mobilu z toho neco videl. Je nutne osetrit pripad, aby se od jedne chyby nevysypala zaplava SMS.
Pokud se v textu zpravy objevi >>JMENOLOKALITY<<, preposle se zprava jeste na emailovou adresu spravce teto lokality (cili dalsi konfigurak). Jedna se o situace, kdy se v lokalite X stane neco, co se tyka lokality JMENOLOKALITY.

Jinak potrebujeme, abychom byli schopni snadno sledovat sledy akci, ktere se v ramci jedne transakce deji na ruznych komponentach. To se nam bude velmi spatne delat, pokud ten logging bude rozhazeny do mnoha souboru nebo nekde v MySQL. Osobne soudim, ze nejlepe se veci hledaji GREPem. Proto v prvni fazi navrhuji sypat vsechno do jednoho textoveho logu a samozrejme u kazde zpravy zapisovat facility i debugLevel. Paralelne s tim mozno do MySQL a nahodit pro vzdalene prohlizeni PHPMyEdit.

V mysql logovat do 1 tabulky, a v ni udrzovat jen poslednich (treba) 7 dni, v archivni tabulce treba posledni mesic.

Citováno z „http://infra2.cs.vsb.cz/vl-wiki/index.php/Virtlab:LoggingDebugging“

Kategorie: Komponenty virtlabu

 Příklad použití viz [https://vl-test.cs.vsb.cz/websvn/filedetails.php?repname=virtlab&path=%2FDISTR%2Fsrc%2Flogging%2Fsrc%2Fvl-debug-test.sh&rev=0&sc=0  vl-debug-test.sh].
+'''Není-li zavoláno INITLOGGING a promenna VGLLOG_FACILITY není nastavena (zděděna), nastavuje se na VLLOG_UNDEFINED a zprávy se logují s facility local8.'''
 == Ukladani zaznamu, ohlasovani chyb e-mailem ==