Error Log formater should containt context

[Halama]

https://github.com/keboola/php-component/blob/96d34caa68708a753c559f253edeeb825039d4cd/src/Logger.php#L59

https://github.com/keboola/php-component/pull/28/files#r188015982

[tomasfejfar]

Jasně - ten "errorLog" padá celý do papertrailu pak. Takže tam dává smysl mít k tomu i ty další věci. Ale pro ten "log" je ta jen message správně, chápu to správně?

[Halama]

jj přesně tak, ten kontext atd. jenom pro errorLog a standardní log nechat jenom message.

[Halama]

ještě by mě teda zajímalo co @pivnicek vedlo k téhle úpravě https://github.com/keboola/db-extractor-common/commit/09c6fd56838cf43ffc0c55985dc32a19f6b4b8c0#diff-a6bfadf6e476180bac436fced8a2e014

[Halama]

např. u writerů je to ok https://github.com/keboola/db-writer-common/blob/master/src/Logger.php a analytics taky https://github.com/keboola/google-analytics-extractor/blob/master/src/Keboola/GoogleAnalyticsExtractor/Logger/Logger.php

Uff, ještě že už máme php-component a už to nebude takhle rozházený všude :)

[tomasfejfar]

Tam je vůbec zajímavé, že se error-loguje všechno od notice výše.

[Halama]

co vím tak nikde moc jiného nelogujeme, jako že bud info nebo error...

[odinuv]

ten context a extra se zamerne nekde vyhazoval (slo by dohledat na slacku), protoze nekomu vadilo, ze tam je porad [] [] a totez s casem - ve storage eventech jsou pak casy dva.

to [] [] je resitelny nestandardnim formatterem, ktery to prazdne nebude vypisovat

jinak formatter by mel byt podle me stejny pro err i info, protoze proste obe veci jdou do eventu

[Halama]

to souvisi s tim ze docker runner to neumi poslat jenom do PT. V tuhle chvili je to absolutne nedebugovatelny pokud jde do PT jen message.

[Halama]

takze ted urcite tak ze to posila context do error logu

[odinuv]

no to neni ale "ted", proste pokud komponenta stdout posle message a kontext, tak docker runner nikdy nepozna, co z toho ma poslat kam, protoze dostane proste nejakej flak textu (kvuli OB navic jeste casto slepenej z vic zprav), jedina cesta ven je ten message mit strukruovany (cili gelf) se stdout/stderr loggerem muzeme udelat maximalne to, aby to vsechen stderr poslalo jen do pt a uzivali zobrazilo jen stdout cili puvodni myslenka byla takova, ze stdout/stderr bude na jednoduchy veci a strukturovany pujdou pres gelf jestli chcem logovat context pres stdout, tak bude vzdycky v eventech

[Halama]

tak ty komponenty pak musi mit gelf, protoze takhle je to nepouzitelny

[Halama]

ale ten gelf mi ale zatim taky neprijde uplne pouzitelny https://keboola.slack.com/archives/C09U3R1J4/p1526301111000369

[Halama]

nevermind, zkusim to udelat jinak, kazdopadne plati, ze trace ma jit na stderr

a to je presne to o co mi tady jde

https://keboola.slack.com/archives/C31U6BGJC/p1525878243000655?thread_ts=1525874098.000502&cid=C31U6BGJC

[Halama]

https://keboola.slack.com/archives/C31U6BGJC/p1525874098000502

Jestli jsem to pochopil správně tak to kumuluje error output. Proč to v případě exit code > 1 nehodí dummy internal error zprávu a jinak at to vyplivne to co to pochytalo?

[odinuv]

celkem souhlas

jsou podle me 3 moznosti:

1. v logu pouzivat jen message, mit lineformatter na message a trace vypisovat na stderr:

   try {
   $app = new MyComponent\Component();
   $app->run();
   exit(0);
   } catch (\Keboola\Component\UserException $e) {
   echo $e->getMessage();
   exit(1);
   } catch (\Throwable $e) {
   error_log(get_class($e) . ':' . $e->getMessage());
   error_log("\nFile: " . $e->getFile());
   error_log("\nLine: " . $e->getLine());
   error_log("\nCode: " . $e->getCode());
   error_log("\nTrace: " . $e->getTraceAsString() . "\n");
   exit(2);
   }

2. mit defaultni lineformatter, pouzivat libovolny parmetery loggeru a smirit se s tim, ze veskery kontext jde do eventu
3. gelf (nebo jinej strukturovanej log, kterej nemame :)

Ve vsech pripadech by to potom melo fungovat tak, ze: do eventu jde info, (warn), err krome situace kdy komponenta skonci app errorem, kdy se ma vsekerej err stopit a poslat jen do PT a uzivateli zobrazit dummy hlasku

coz by melo byt z vetsi casti fixly tady https://github.com/keboola/docker-bundle/pull/293 (ale chci to jeste znovu projit, je to pomerne dost kombinaci)

[Halama]

jeste me napadlo ze jedine kdy te zajima ten kontext je application error. Tzn. ze by logger fungoval jako 1) mel by proste jenom Line formatter s message a vse slo do event. A v pripade application error by clovek pred exit code 2 mel moznost dumpnout ten stack trace do nejakeho souboru ktery by docker runner potom poslal do S3 a PT.

[odinuv]

no, vsak to v te 1) staci - v pripade app-err dumpnes trace na stderr a docker runner ho posle jen do PT (a syrup do S3), pokud se tady https://github.com/keboola/php-component/blob/master/example/run.php vymeni echo za error_log a mergne tohle https://github.com/keboola/docker-bundle/pull/293 tak to tak bude fungovat

[Halama]

Je ta 1) teda stejná jako? V tomhle ani imho tom tvem pripade nebudou user error eventy cervene.

$errHandler = new StreamHandler('php://stderr', \Monolog\Logger::CRITICAL, false);
$handler = new StreamHandler('php://stdout',  \Monolog\Logger::INFO);
$handler->setFormatter( new LineFormatter("%message%\n"));
$logger = new \Monolog\Logger('app', [$errHandler, $handler]);

try {
    $app = new MyComponent\Component();
    $app->run();
    exit(0);
} catch (\Keboola\Component\UserException $e) {
    $logger->error($e->getMessage());
    exit(1);
} catch (\Throwable $e) {
   $logger->critical($e->getMessage(), [
        'errFile' => $e->getFile(),
        'errLine' => $e->getLine(),
        'trace' => $e->getTrace()
    ]);
    exit(2);
}

[odinuv]

pardon, takhle to ma byt

try {
    $app = new MyComponent\Component();
    $app->run();
    exit(0);
} catch (\Keboola\Component\UserException $e) {
    error_log( $e->getMessage());
    exit(1);
} catch (\Throwable $e) {
    error_log(get_class($e) . ':' . $e->getMessage());
    error_log("\nFile: " . $e->getFile());
   error_log("\nLine: " . $e->getLine());
    error_log("\nCode: " . $e->getCode());
    error_log("\nTrace: " . $e->getTraceAsString() . "\n");
    exit(2);
}

[Halama]

jo jasne, to mi tam nesedelo. Tak potom by to mohlo byt takhle, coz je snad to samy jenom s loggerem.

$appErrHandler = new StreamHandler('php://stderr', \Monolog\Logger::CRITICAL, false);
$userErrHandler = new StreamHandler('php://stderr', \Monolog\Logger::ERROR, false);
$userErrHandler->setFormatter( new LineFormatter("%message%\n"));
$handler = new StreamHandler('php://stdout',  \Monolog\Logger::INFO);
$handler->setFormatter( new LineFormatter("%message%\n"));
$logger = new \Monolog\Logger('app', [$appErrHandler, $userErrHandler, $handler]);

try {
    $app = new MyComponent\Component();
    $app->run();
    exit(0);
} catch (\Keboola\Component\UserException $e) {
    $logger->error($e->getMessage());
    exit(1);
} catch (\Throwable $e) {
   $logger->critical($e->getMessage(), [
        'errFile' => $e->getFile(),
        'errLine' => $e->getLine(),
        'trace' => $e->getTrace()
    ]);
    exit(2);
}

[odinuv]

jo, to by melo fungovat

[Halama]

a ono to bufferovani toho error outpuptu az nakonec ted fakt funguje?

[Halama]

podle tohodle https://github.com/keboola/docker-bundle/issues/236#issuecomment-361575068 mi prijde ze ne. nebo je to stary issue?

[odinuv]

jo funguje - stdout/stderr (u gelfu si nejsem jistej), akoratze se vyprintuje i pri apperr, ten screen je stary

[Halama]

ok, přijde mi to bufferování trochu divný ale imho by většina appek na stderr nic sypat během běhu stejně neměla....

[odinuv]

jo je, proto jsem udelal tu issue https://github.com/keboola/docker-bundle/issues/236, kdyby to pak koncilo warningem (a kdyby se ten event jeste nejak vizualne oddelil), tak uz by to tak moc divny nebylo

kazdopadne prubezne se to vypisovat nemuze, pokud se to ma v pripade apperru skryt

[Halama]

ja bych to klidne nechal vypisovat. jenom by se proste stack trace neposilal na stderr ale dumpnul by se bokem do souboru. Ale jinak to reseni 1) s tim bufferovanim mi taky prijde cajk celkem...

[odinuv]

no tak to asi celkem neni problem udelat neco jako ze '/data/error.trace` se hodi do PT, mohlo by to pak generovat citelnejsi tracy, ale nedelam si moc velky iluze, ze by se to ujalo mezi 4th party vyvojarema

[ondrejhlavacek]

nemusel by to bejt error.trace, ale nějakej obecnej log, kterej bude v eventech skrytej a jen se uploadne někam, kde k němu budeme mít přístup my a potenciálně i 3rd party developer pro debug. pokud by se na to aplikoval filtr na zašifrovaný hodnoty, tak by to mohlo bejt i trochu bezpečný, nicméně leaky dat tam hrozí tak jako tak :-(

[Halama]

ty leaky hrozej v obou pripadech imho uplne stejne, je jedno jakym zpusobem to leze ven.

Ted bych se asi ale spokojil s merge https://github.com/keboola/docker-bundle/pull/293#pullrequestreview-120110154 ktery zajisti ze to pri internal error neposle error log uzivateli ale preda ho jenom do PT v kombinaci s https://github.com/keboola/php-component/issues/29#issuecomment-388968195

[odinuv]

solved by 0ad130af164510b44b8b944cda545e4db64dc304

[MiroCillik]

Inak nemalo by tu byt spis level NOTICE misto WARNING? https://github.com/keboola/php-component/blob/0ad130af164510b44b8b944cda545e4db64dc304/src/Logger.php#L60

[odinuv]

nemelo https://github.com/Seldaek/monolog/blob/master/doc/01-usage.md#log-levels NOTICE (250): Normal but significant events.