Project

General

Profile

Actions

Task #522

closed

Log/backtrace při chybě klientské knihovny

Added by Pavel Kácha over 12 years ago. Updated about 12 years ago.

Status:
Closed
Priority:
Normal
Assignee:
Jan Soukal
Category:
-
Target version:
Start date:
08/13/2012
Due date:
08/29/2012
% Done:

0%

Estimated time:

Description

Nastane-li neobvyklý stav mimo běžný princip hlášení chyb, je třeba zalogovat potřebné údaje pro ladění vývojáři (backtrace, errno, informace signálu aj.)


Related issues

Related to Warden - Task #520: Volitelný způsob logování pro klientskou knihovnuClosedJan Soukal07/30/201208/29/2012

Actions
Actions #1

Updated by Pavel Kácha over 12 years ago

  • Target version changed from 2.1 to Future
Actions #2

Updated by Pavel Kácha over 12 years ago

  • Assignee set to Jan Soukal
Actions #3

Updated by Pavel Kácha over 12 years ago

  • Due date deleted (08/13/2012)
Actions #4

Updated by Pavel Kácha over 12 years ago

  • Due date set to 08/22/2012

A lehká změna plánu - došel jsem k závěru, že logování pro pro klientskou knihovnu bude stejně výrazně jiné (jednodušší) od serveru, takže nemá smysl čekat na Toma.

Takže - dokážeme rozumně použít Carp::confess? Půjde poslat do syslogu (souvisí s #520), případně na stderr a současně do syslogu, bez ovlivnění volající aplikace?

Actions #5

Updated by Pavel Kácha over 12 years ago

  • Target version changed from Future to 2.1

Případně Carp::longmess.

Krom toho by bylo vhodné podívat se na možné chyby při voláních a zvážit výpis dalších užitečných dat, příklad viz #532.

Actions #6

Updated by Pavel Kácha over 12 years ago

  • Due date changed from 08/22/2012 to 08/26/2012
Actions #7

Updated by Pavel Kácha over 12 years ago

  • Due date changed from 08/26/2012 to 08/29/2012

Pokud půjde backtrace takhle jednoduše, myslím, že to bude rovnou součást #520, dal jsem jim souvislost a stejná data.

Actions #8

Updated by Jan Soukal over 12 years ago

Tak jsem si zkousel s knihovnou Carp a vychazi mi z toho nasledujici:
  • k zaznamenani stacku bych pouzil Carp::longmess()
    • Carp::confess pise na STDERR (coz implicitne nechceme) a nasledne vola die
    • Carp::cluck pise na STDERR (coz implicitne nechceme)
    • Carp::longmess() vraci totez, co predesle dve, ale nikam nepise a nevola die ani nic jineho
  • fci errMsg bych rozsiril prave o longmess() v pripade, ze bude v konfiguraku zapnuty nejaky prepinac, ze chce uzivatel zaznamenavat s errory i stav na zasobniku:
    sub errMsg
    {
      my $msg = shift;
    
      if ($BACKTRACE) { # uzivatel chce videt stack
        $msg .= "\nStack info: " . Carp::longmess() . "\n";
      }
    
      die ($msg);
    
    } # End of errMsg
    
  • vetev nasledujici eval, pokud se vyskytne chyba ($@), bych potom upravil tak, aby zohlednovala kam vsude chce uzivatel chyby reportovat (STDERR, Syslog, soubor?):
     } # End of eval block
      or do {
        if ($STDERR) {
          # pis $@ na STDERR
        }
        if ($SYSLOG) {
          # posli do Syslogu
        }
        if ($WHATEVER) {
          # posli jinam...
        }
        return;
      };
    
Problem ale jsou chyby uvnitr externich knihoven (SOAP a spol.), kde se pripadne vola die() a my jej odchytime az na urovni evalu
  • Jako naplast vidim moznost si primo nadefinovat die, aby fungoval jako vyse popsana errMsg()
      $SIG{__DIE__} = sub {
        # delej totez co errMsg
        # ...
      }
    
  • v kodu pak misto volani errMsg("...") budeme proste volat die("..."). Stejne to tak na mnoha mistech v kodu je.
  • kazdopadne jeste jsem to nezkousel (zkusim v pondeli). Takze pokud nekdo dopredu vite, ze je to slepa ulicka nebo to lze resit jinak (a lepe), dejte vedet.
Actions #9

Updated by Pavel Kácha over 12 years ago

Co se týče errMsg a eval - znamená to, že hlášky do stderr a syslogu budou stejné, nedokážeš nastavit méně ukecaný stderr a ukecanější syslog, jak jsi navrhoval. Nicméně je to v současné situaci nejjednodušší způsob. Dovolit různou ukecanost do různých cílů jde výjimkami asi jen tak, že začneš vyhazovat místo stringových výjimek objektové (stacktrace zvlášť, catch si vybere co chce kam).

Druhá varianta je v našem kódu se zbavit výjimek (a toplevel eval nechat jen jako bezpečnostní pojistku na cizí knihovny) a chyby řešit ne jako ... or die("asdf"); kde errMsg hází die(), ale jako ... or {errMsg("asdf"); return 0;}; nebo or (errMsg("asdf") and return 0); (0 nebo undef podle kontextu funkce). Tím se ale kód dost zanese řešením výjimečných stavů.

Osobně jsem v současné době pro se spokojit s první variantou - vyměnit zapomenutá die() za errMsg() a udělat to tak, jak navrhuješ - do errMsg doplňovat longmess a v catch větvi vyřešit logování. Místo $BACKTRACE bych spíš použil něco jako $LOG_VERBOSE.

K DIE: nesmíme zapomínat, že nejsme aplikace, ale knihovna - neměli bychom manipulovat prostředím volající aplikace - ta si mohla nastavit vlastní handler na DIE a my bychom museli zařizovat řetězení (což může dělat i volající aplikace a někde se srazíme). Navíc se chytání DIE nedoporučuje, a perlisti ho mají v plánu upravit tak, že bude volán jen při ukončování programu. Ergo - myslím, že pokud nedostaneme stack z externích knihoven, budeme se muset spokojit jen stackem našeho kódu. Na místech, podezřelých z možnosti vyhození výjimky bych se alespoň snažil ji chytit včas a doplnit širší chybovou hlášku s kontextem, jako jsem třeba doplnil u volání $soap->deserializer->deserialize.

Actions #10

Updated by Jan Soukal over 12 years ago

Pavel Kácha wrote:

Co se týče errMsg a eval - znamená to, že hlášky do stderr a syslogu budou stejné, nedokážeš nastavit méně ukecaný stderr a ukecanější syslog, jak jsi navrhoval.

Ano, to mas pravdu. "Neakademicky" by to slo vyresit tak, ze bychom si z errMsg predali retezec, v nemz by byla nejak otagovana jak cast s pouhou hlaskou tak i vypis stacku. V catch vetvi bychom to jednoduse rozparsovali. Neco jako:

  <warden-client-err-msg>...toto je chybova hlaska...</warden-client-err-msg>
  <warden-client-err-stack>...zde je info o stacku...</warden-client-err-stack>

Osobně jsem v současné době pro se spokojit s první variantou - vyměnit zapomenutá die() za errMsg() a udělat to tak, jak navrhuješ - do errMsg doplňovat longmess a v catch větvi vyřešit logování. Místo $BACKTRACE bych spíš použil něco jako $LOG_VERBOSE.

Souhlasim. $BACKTRACE byl pouze pro nazornost, do kodu jsem dal $LOG_VERBOSE.

K DIE: nesmíme zapomínat, že nejsme aplikace, ale knihovna - neměli bychom manipulovat prostředím volající aplikace - ta si mohla nastavit vlastní handler na DIE a my bychom museli zařizovat řetězení (což může dělat i volající aplikace a někde se srazíme). Navíc se chytání DIE nedoporučuje, a perlisti ho mají v plánu upravit tak, že bude volán jen při ukončování programu. Ergo - myslím, že pokud nedostaneme stack z externích knihoven, budeme se muset spokojit jen stackem našeho kódu. Na místech, podezřelých z možnosti vyhození výjimky bych se alespoň snažil ji chytit včas a doplnit širší chybovou hlášku s kontextem, jako jsem třeba doplnil u volání $soap->deserializer->deserialize.

Souhlas.

Actions #11

Updated by Pavel Kácha over 12 years ago

Parsování stringu je zvrhlost, od toho jsou objektové výjimky - a tak daleko jít zatím nepotřebujeme. Implementuj tu variantu $LOG_VERBOSE (společnou pro stderr i syslog).

Actions #12

Updated by Jan Soukal over 12 years ago

Dokoncil jsem logovani na STDERR a/nebo do Syslogu (revize 57c407e3). Chovani se nastavuje v konfiguraku.

TODO:
  1. Format (prehlednost) ulozeni stavu zasobniku, new-liny, hlasky, atd. Zatim to vypada dost neprehledne:
      Sep  3 16:08:34 warden-c Warden-client:[19802]: Warden-client unexpected end in eval block.
    Error message: test error in c2s()
    Stack info:  at /home/soukal/client-test/2.0.0_beta/warden-client/lib/WardenClientSend.pm line 57
            WardenClientSend::c2s('https://warden-dev.cesnet.cz:443/Warden', '/home/soukal/client-test/2.0.0_beta/warden-client/etc/warden-...', '/home/soukal/client-test/2.0.0_beta/warden-client/etc/warden-...', '/etc/ssl/certs/tcs-ca-bundle.pem', 'saveNewEvent', 'SOAP::Data=HASH(0x14de6468)') called at /home/soukal/client-test/2.0.0_beta/warden-client/lib/WardenClientSend.pm line 146
            eval {...} called at /home/soukal/client-test/2.0.0_beta/warden-client/lib/WardenClientSend.pm line 148
            WardenClientSend::saveNewEvent('/home/soukal/client-test/2.0.0_beta/warden-client', 'ARRAY(0x152500e8)') called at ./doc/example-sender.pl.txt line 55
    
    
  2. Co s die() ve WardenClientConf.pm? Nechat tak?
Actions #13

Updated by Pavel Kácha over 12 years ago

  1. Se stacktrace nic nevymyslíme, ostatní vypadá smysluplně. Uvidíme časem z reálných hlášek.
  1. Vzhledem k tomu, že jsi do obou klientů přidal spoustu duplicitního kódu, spolu s c2s jsou to všechno adepti na vytažení někam mimo. Jaké jsou možnosti?
Actions #14

Updated by Jan Soukal over 12 years ago

Pavel Kácha wrote:

  1. Se stacktrace nic nevymyslíme, ostatní vypadá smysluplně. Uvidíme časem z reálných hlášek.

OK.

  1. Vzhledem k tomu, že jsi do obou klientů přidal spoustu duplicitního kódu, spolu s c2s jsou to všechno adepti na vytažení někam mimo. Jaké jsou možnosti?
Nadhodil jsem reseni v revizi 9178c6bd. Ve zkratce:
  • premistil jsem fce errMsg() a c2s() z WardenClientSend/Receive do WardenClientConf
  • "globalni" promenne z konfiguraku jsou ted globalni v WardenClientConf
  • v samotnych WardenClientSend/Receive zustava asi zbytecna spousta predavanych promennych
    • napr. c2s() si muze udaje pro spojeni se serverem brat primo z promennych ve WardenClientConf
  • bude to asi chtit vymyslet vhodnejsi nazev pro WardenClientConf
  • muzeme rovnou i na die() ve WardenClientConf volat errMsg()

Otestoval jsem zatim tak "by vocko" - sender odesila, funkci u prijimace bohuzel kvuli SQL erroru (#547) nemuzu potvrdit. Jakmile se vratim z dovolene, pekne bych to ucesal.

Souhlas nebo na to pujdeme jinak?

Actions #15

Updated by Pavel Kácha over 12 years ago

Dobře - když už jsi do toho řízl jsem pro. Jen bych to rozdělil na WardenClientConf a například WardenCommon. Do WardenCommon bych strčil c2s a errMsg, ve WardenClientConf bych nechal čtení konfiguráku.

Konfigurační proměnné bych udělal our v rámci package WardenClientConf a loadConf v ní spouštěl automaticky při importu (tj. vlastně zrušil scope "sub loadConf {" a "}"), to znamená, že v ostatních modulech po "import WardenClientConf" bude k dispozici $WardenClientConf::LOG_SYSLOG a další. Jen bych otestoval, zda 'use' opravdu importuje jen jednou, ne opakovaně, pokud bude použito i z WardenClientCommon i z WardenClientReceive.

A poznámka k importu - v takhle jednoduchém kódu bych použil "import WardenCommon qw(errMsg c2s); import WardenClientConf qw(uri ssl_key_file ssl_cert_file ssl_ca_file max_rcv_events_limit LOG_STDERR LOG_SYSLOG LOG_SYSLOG_FACILITY LOG_VERBOSE);" a kód se následně bude muset měnit minimálně (nebude potřeba přidávat všude namespace WardenClientConf:: nebo WardenClientCommon::).

Navrhoval bych pak názvy konfiguračních proměnných sjednotit na verzálky.

Co si o tom myslíš?

Actions #16

Updated by Jan Soukal about 12 years ago

V revizi 5b557ca0 je rozpracovano vyse popsane.

Mam ale problem: Vzhledem k tomu, ze package WardenClientConf a WardenClientCommon se nacitaji az v run-timu (v compile-timu nezname domovsky adresar Wardenu, kam si pak sahame pro knihovny a konfiguraky), nelze vyuzit use (ktery se provadi v compile-timu). Pri pouziti require (ktere jde az v run-timu) nemuzu prijit na to, jak importovat nazvy promennych a funkci z techto dvou package do jmenneho prostoru "nadrazene" WardenClientReceive (resp. Send). Problem nastava na radcich 37 az 41 ve WardenClientReceive.pm.

Nevite nekdo, jak na to?

Actions #17

Updated by Pavel Kácha about 12 years ago

Nezkoušel jsem, ale nefungovalo by WardenClientConf->import() po require?

http://perldoc.perl.org/functions/use.html

Actions #18

Updated by Pavel Kácha about 12 years ago

Takže se s tím neštvi. Otestoval jsem to, import napopuluje namespace jen je-li volán v čase kompilace (v BEGIN {}). Bude holt potřeba konfigurační proměnné odkazovat jako WardenClientConf::LOG_VERBOSE, atd. Následující funguje bez problémů:

perlexporttest.pm

package perlexporttest;

our $FOO = 32;
our $BAR = 42;

$FOO = 20;

1;

perlrequiretest.pl

require "perlexporttest.pm";

print $perlexporttest::FOO, "\n";
print $perlexporttest::BAR, "\n";

Actions #19

Updated by Jan Soukal about 12 years ago

Hotovo v revizi 22e198b4.

Zbyva:
  • Dusledneji otestovat. Zatim jsem to zkousel jen tak od pasu. Ale funguje
  • Zrejme bude vhodne kod prekomentovat, aby byl pochopitelny i pro nezasvecene. I kdyz je jednoduchy, nemusi byt na prvni pohled zrejme, o co jde.
Actions #20

Updated by Jan Soukal about 12 years ago

  • Status changed from New to Resolved

Hotovo, myslim, ze muzeme uzavrit.

Actions #21

Updated by Pavel Kácha about 12 years ago

  • Status changed from Resolved to Closed
Actions

Also available in: Atom PDF