New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Enable fingers crossed handler via INI config and show backtrace in logs/archive api output #13923

Open
wants to merge 10 commits into
base: 3.x-dev
from

Conversation

Projects
None yet
3 participants
@diosmosis
Copy link
Member

diosmosis commented Dec 30, 2018

Fixes #8698
Fixes #8616

Tested in the following contexts:

  • web request (w/ warning/error all logs written to file log, only warning/error shows up in screen)
  • normal console command (fingers crossed handler not used)
  • core:archive top level command (fingers crossed handler not used)
  • core:archive climulti processes (w/ warning/error all logs written to file log
  • when a fatal error occurs

Also made following changes:

  • log more exceptions
  • make backtrace in logs include previous exceptions' backtraces
  • don't use screen writer if in CLI mode (so notifications don't end up on the screen when we don't want them to). could also add a check for trigger=archivephp.
  • always print backtrace if in CLI mode & trigger=archivephp

CC @tsteur not sure which milestone to put this in

@@ -104,6 +104,14 @@
; if configured to log in a file, log entries will be made to this file
logger_file_path = tmp/logs/piwik.log

; if set to 1, will enable monolog's FingersCrossedHandler, which buffers all logs and flushes them if a warning or error

This comment has been minimized.

@tsteur

tsteur Dec 30, 2018

Member

I wonder if it actually needed to have an option for it or always enable it?

This comment has been minimized.

@diosmosis

diosmosis Dec 30, 2018

Member

ATM I'm not sure what effect this will have in production, thought it could use some more testing before it's enabled by default. I suppose it wouldn't be useful for most users anyway? Unless we create some sort of bug summary feature that grabbed these logs so users could upload these w/ error reports.

This comment has been minimized.

@tsteur

tsteur Dec 31, 2018

Member

I reckon it would always be useful to have it enabled so we get detailed logs when we ask users to enable it etc. Could also leave the option, test it for now on production, and follow up to remove the setting in 2 or 3 months and have it always enabled.


; if enable_fingers_crossed_handler is set to 1, and this is set to 1, then the FingersCrossedHandler will stop buffering
; on the first warning/error. if another one occurs later in the request, there will be no extra debug logs for them.
fingers_crossed_stop_buffering_on_activation = 0

This comment has been minimized.

@tsteur

tsteur Dec 30, 2018

Member

what's the use case for this one?

This comment has been minimized.

@diosmosis

diosmosis Dec 30, 2018

Member

FingersCrossedHandler has an option where it stops buffering after the first error. I assume it's to avoid buffering too many logs in case there are lots of errors? I'm not exactly sure, but figured someone might want to set it true (by default I've left it disabled so every error triggers debug logs to be flushed).

This comment has been minimized.

@tsteur

tsteur Dec 31, 2018

Member

Same here I reckon we could keep the setting and see how it behaves in production and then possibly remove the setting and always have it disabled but to be seen after some more testing

@tsteur tsteur added this to the 3.9.0 milestone Dec 30, 2018

Make sure more exceptions make it to the logs, make backtrace include…
… previous exceptions, do not use screen writer if in cli mode, always print backtrace if in CLI mode and archivephp triggered.
@tsteur

This comment has been minimized.

Copy link
Member

tsteur commented Dec 30, 2018

I'll put it into 3.9 for now. Can other plugins get all the logged messages during runtime? To send them eg by email

@diosmosis

This comment has been minimized.

Copy link
Member

diosmosis commented Dec 30, 2018

@tsteur added some more changes just now, might want to have another look.

Can other plugins get all the logged messages during runtime?

Not at the moment. We could create a custom FingersCrossedHandler that posts an event when triggered. Or the plugin could grep the logs using the current request ID (that's what I was thinking at first).

@diosmosis diosmosis changed the title Enable fingers crossed handler via INI config Enable fingers crossed handler via INI config and show backtrace in logs/archive api output Dec 30, 2018

@tsteur

This comment has been minimized.

Copy link
Member

tsteur commented Dec 31, 2018

when eg a fatal error occurs, we're sending an email during that request and looking through logs is not really an option as the log files could be many GB big. It would be great if there was some static method or some way to get the logger instance with all the log messages without using events (re performance).

@diosmosis

This comment has been minimized.

Copy link
Member

diosmosis commented Dec 31, 2018

I'm not sure there is a way to do that currently. I think FingersCrossedHandler will abandon the saved logs once they are flushed to the internal handler, so they're not all retained. I guess we can try to extend/modify the handler.

Will we ever look into something like loggly/cloudwatch/etc.? If the logs were more easily accessible to us, it might not be needed to have them attached to an email (just a request ID would suffice).

@tsteur

This comment has been minimized.

Copy link
Member

tsteur commented Dec 31, 2018

We will likely look into CloudWatch eventually but we wouldn't send any data to a 3rd party.

I thought there would be maybe some logging handler or writer that could be put in between maybe?

@tsteur

This comment has been minimized.

Copy link
Member

tsteur commented Dec 31, 2018

Also the goal is really to have all information directly in the fatal error email to have immediately all information.

@diosmosis

This comment has been minimized.

Copy link
Member

diosmosis commented Jan 3, 2019

@tsteur Added the ability to get all logs in a request using a new handler. Also removed the INI config from global.ini.php and just check for them in code, so it's easier to remove if we find we don't need to include them later.

@@ -269,7 +271,9 @@ public function process()
return $response->getResponse($returnedValue, $module, $method);
});
} catch (Exception $e) {
Log::debug($e);
StaticContainer::get(LoggerInterface::class)->error('Uncaught exception in API: {exception}', [

This comment has been minimized.

@tsteur

tsteur Jan 3, 2019

Member

I wonder if we should keep debug level when it is fetched through UI to not expose the specific error here? just not sure if there could be any problem such as sensitive information or something. Likely not a problem though.

This comment has been minimized.

@diosmosis

diosmosis Jan 3, 2019

Member

If it's not debug, it won't trigger the fingers crossed handler, BUT I made sure the screen handler doesn't get wrapped in the fingers crossed handler. So I think this will result in an exception displaying on the screen for UI requests, but it should just print the exception message, which is the current behavior right? I'll make sure to see exactly what happens.

This comment has been minimized.

@tsteur

tsteur Jan 3, 2019

Member

Was just not sure whether it could have any side effects re the exception message re security or whether it could be any annoying or cause any other problems. Wonder if it would even show during an API request etc or what would happen then? I wonder if we need to add tests for all those cases where this error is triggered.

This comment has been minimized.

@diosmosis

diosmosis Jan 3, 2019

Member

Would be nice to have tests, though I'm not sure how we'd verify. Eg, if we trigger an error in a PHPUnit test, how do we test if a message showed up on the screen? Could use a UI test, but that might get complicated to write and may not be worth it...

Would be easier w/ headless chrome, then we'd be able to pull in npm packages to make it easier to verify things like "did this get logged to the file log".

This comment has been minimized.

@tsteur

tsteur Jan 3, 2019

Member

I meant mainly to make sure that the API output is still correct when an error occurs during an API request. Might be even good for one UI test to see what it shows there. Wouldn't need to check re what is logged to the file.

This comment has been minimized.

@diosmosis

diosmosis Jan 4, 2019

Member

Created a UI test and noticed that the error will also appear as a notification. Not sure what the best way to handle this is, since w/o the log statement, there ends up being no record of the error in the file.

My personal opinion is that there really shouldn't be a screen logger, and everything should go into a log that only admins/devs can see. But I'm not sure if that change can be made.

This comment has been minimized.

@tsteur

tsteur Jan 4, 2019

Member

That's what I meant with changing the log level from debug to error. The screen logger is definitely useful in that it helps us finding bugs/issues etc. where otherwise 98% of users would never look in the logs and not even know they exist etc.

The only thing I can think of be to change the log level depending on whether we are CLI or not. Or also enable the fingercrossedhandler on cli based on some other flags maybe. Can we maybe log it as debug and somehow pass some option to also attach all previous logs when this happens? Defeats the idea of the fingercrossedhandler maybe a little but could work maybe?

This comment has been minimized.

@diosmosis

diosmosis Jan 4, 2019

Member

We could also go in similar, but opposite route, add a property to the ::error() calls to ignore by the screen handler, eg:

->error("...", [
    'exception' => $ex,
    'handledInUI' => true, // or maybe 'ignoreInScreenWriter' to be more generic
]);

So anywhere we print the exception or don't want it to be displayed in the UI, we can add that to the log. What do you think? This way it keeps the meaning of FingersCrossedHandler.

This comment has been minimized.

@tsteur

tsteur Jan 6, 2019

Member

Sure it should be fine this way as well 👍

This comment has been minimized.

@diosmosis

diosmosis Jan 7, 2019

Member

Made the change + added some more logs. Also modified ExceptionToTextProcessor to replace {exception} in the message instead of the whole message.

@@ -41,6 +44,8 @@ public static function handleException($exception)
*/
public static function dieWithCliError($exception)
{
self::logException($exception);

This comment has been minimized.

@tsteur

tsteur Jan 3, 2019

Member

Likely not too important but just realising that console is doing eg Piwik\ExceptionHandler::setUp(); (and also Piwik\ErrorHandler::registerErrorHandler();) before the environment is loaded and container is built. So there could be under circumstances a problem where a message is maybe logged but the container is not ready yet. Not sure what would happen and likely the chances are maybe low there is an error between registering error handler and loading environment...

This comment has been minimized.

@tsteur

tsteur Jan 3, 2019

Member

actually stupid of me... I'm just seeing you catch an exception there anyway. Forget the comment :)

'exception' => $exception,
]);
} catch (ContainerException $ex) {
// ignore (occurs if exception is thrown when resolving DI entries)

This comment has been minimized.

@tsteur

tsteur Jan 3, 2019

Member

lets maybe also catch ContainerDoesNotExistException in case the container is not set up yet?

This comment has been minimized.

@diosmosis
@@ -107,6 +108,10 @@ private static function generateSafeModeOutputFromError($lastError)
*/
private static function generateSafeModeOutputFromException($e)
{
StaticContainer::get(LoggerInterface::class)->error('Uncaught exception: {exception}', [

This comment has been minimized.

@tsteur

tsteur Jan 3, 2019

Member

wouldn't that make the error visible in the UI?

This comment has been minimized.

@diosmosis

diosmosis Jan 3, 2019

Member

Wouldn't it always be visible in the UI? If it's not logged, there won't be information about it in the logs (and it won't trigger fingers crossed).

This comment has been minimized.

@tsteur

tsteur Jan 3, 2019

Member

Not quite. Eg on Cloud we do not want to show the actual exception and we overwrite the safemode controller action for this. I think under circumstances we would also show the error even if not wanted. Eg in safemode we replace the actual error message for anonymous with A fatal error occurred. . Haven't tested though whether it would actually show this message in the UI. Also not sure what happens for API calls etc.

@tsteur

This comment has been minimized.

Copy link
Member

tsteur commented Jan 3, 2019

Also removed the INI config from global.ini.php and just check for them in code, so it's easier to remove if we find we don't need to include them later.

should we maybe create a follow up issue for 3.9 or 3.10 to enable it by default if our tests go well?

@diosmosis

This comment has been minimized.

Copy link
Member

diosmosis commented Jan 3, 2019

should we maybe create a follow up issue for 3.9 or 3.10 to enable it by default if our tests go well?

Makes sense, will do so once this PR is approved.

@Findus23

This comment has been minimized.

Copy link
Member

Findus23 commented Jan 3, 2019

Will we ever look into something like loggly/cloudwatch/etc.?

It would be amazing if there was an easy way to get all Matomo errors/warnings into sentry.

I originally wanted to integrate Sentry into the Matomo monolog logger, but failed, so at the moment I am just using the default Sentry PHP error logger, which kind of works, but is incredibly hacky and probably doesn't show Matomo errors, just PHP errors and uncaught exceptions.
https://plugins.matomo.org/SentryLogger

Still, using (a self-hosted) Sentry to keep track of Matomo errors has been incredibly helpful as I can keep track of all errors I come across on the server and during development, can see if they occur regularly or just once, have them automatically grouped and see stack traces including all variables that were set during the exceptions.

Screenshot

grafik

So if there is any way (for a plugin) to get all errors and warnings including stack traces in Matomo to send it to Sentry, it would be really helpful for me (and guessing by the fact that nearly 500 people have downloaded the really specific plugin, probably others too).

Having better error backtraces sounds also really useful for debugging odd issues on the forum.

@diosmosis

This comment has been minimized.

Copy link
Member

diosmosis commented Jan 3, 2019

Didn't know about sentry, if there are any issues w/ integrating w/ Matomo that I can help w/, let me know, will probably want to use that on my personal matomo instance ;)

@diosmosis

This comment has been minimized.

Copy link
Member

diosmosis commented Jan 4, 2019

So if there is any way (for a plugin) to get all errors and warnings including stack traces in Matomo to send it to Sentry, it would be really helpful for me (and guessing by the fact that nearly 500 people have downloaded the really specific plugin, probably others too).

@Findus23 Just read this, you could try creating a custom log handler. Exceptions will be in the 'exception' property in the context (see eg how ExceptionToTextProcessor uses the property). I think you could use \DI\add or \DI\decorate w/ 'log.handlers' in your plugin to add it. You won't be able to catch exceptions that aren't logged, but we should probably be logging everything.

diosmosis added some commits Jan 4, 2019

Add some more log statements, ignore logs in screen writer, replace p…
…art of message in ExceptionToTextProcessor instead of whole message.
{
// array of already registered plugins names
protected $alreadyRegistered = array();
private $metadataArray = array();
protected $metadataArray = array();

This comment has been minimized.

@tsteur

tsteur Jan 7, 2019

Member

not 100% sure if this was meant to be in the PR? Seeing there were couple tests for this but not sure if it was meant for different PR maybe?

This comment has been minimized.

@diosmosis

diosmosis Jan 7, 2019

Member

It's used by the new UI test, see CustomApiProxy in UITestFixture.php.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment