@diosmosis opened this Pull Request on January 17th 2019 Member

Instead of Common::printDebug that always prints w/ DEBUG log level and only if tracker debug is on, use the logger directly so error logs will show up in the file logs at least.

I changed some of the printDebugs for errors to error logs so the full stack trace will appear in the file logs, and so they can be potentially combined w/ the fingers crossed handler.

Test scenarios:

  • normal tracking default settings (no error / error)
    No error: no logs
    w/ error: logs in file not in response
  • no tracker debug, debug level log (no error / error)
    no error: debug logs to file, not in response
    w/ error: debug/error logs to file, not in response
  • tracker debug on, warn level (no error / error)
    no error: prints debug logs to response + file
    w/ error: prints debug logs to response + file
@diosmosis commented on February 25th 2019 Member

I tried replacing all of them, but it was taking a long time...

@diosmosis commented on February 26th 2019 Member

CC @tsteur just to make sure there are no potential performance regressions in the tracker

@tsteur commented on February 26th 2019 Member

I would say it should be fine but it does add some unneeded behaviour. Is it maybe possible to still check first for if (isset($GLOBALS['PIWIK_TRACKER_DEBUG']) && $GLOBALS['PIWIK_TRACKER_DEBUG']) {?

@diosmosis commented on February 26th 2019 Member

@tsteur in printDebug() you mean? I could re-add it, though it would mean there would be less logs if we use the tracker w/ the fingers crossed handler.

@tsteur commented on February 26th 2019 Member

@diosmosis yep meant in printDebug. Not sure, I would have thought it still records the same amount of logs as the property PIWIK_TRACKER_DEBUG is enabled quite early in the tracking process?

@diosmosis commented on February 26th 2019 Member

@tsteur I mean PIWIK_TRACKER_DEBUG wouldn't be set in the normal fingers crossed workflow, since you set the log level to WARN or ERROR, then if there is an error/warn log that gets through, print out debug logs too. Ie, we wouldn't set the log level to DEBUG, so we wouldn't set PIWIK_TRACKER_DEBUG. I'm thinking about potential use in production if a tracking request fails and we want to have more info why.

@tsteur commented on February 26th 2019 Member

Not sure. I suppose on production if we wanted these things to be logged we would also set the flag to true. So far I don't think there's a plan to log these but could do. I'm just not sure in general how much code is executed there in all the log handlers and the logger itself and then the var_export etc. so have no idea re performance.

@diosmosis commented on February 26th 2019 Member

Not sure. I suppose on production if we wanted these things to be logged we would also set the flag to true.

Note: in this case it would print debug logs for every request, not just when errors are encountered.

I'm just not sure in general how much code is executed there in all the log handlers and the logger itself and then the var_export etc. so have no idea re performance.

Makes sense, especially in the tracker which would experience the most scale. I can add the check again.

@tsteur commented on February 26th 2019 Member

Yeah I'm just thinking if it's like executed 100mio times it adds up. Looking at the Logger.php there is quite some code around handlers, processors, ...

Note: in this case it would print debug logs for every request, not just when errors are encountered.

I see we probably wouldn't want that either. Not really sure here. I suppose we can just leave the code without the flag check and execute all the logging and change it if/when needed.

@diosmosis commented on February 26th 2019 Member

Actually, I'll add a new flag to short-circuit PIWIK_TRACKER_DEBUG, eg, FORCE_BYPASS_PIWIK_TRACKER_DEBUG. This way there would be no performance issue, and if needed, could test fingers crossed handler by setting the new flag.

@tsteur commented on February 26th 2019 Member

:+1:

@tsteur commented on April 11th 2019 Member

Screenshot at Apr 11 13-38-59
@diosmosis is it supposed to look like this when tracker debug is enabled?

Otherwise looks good if tests pass. I was a bit worried about the logging to file when an error occurs part that it could quickly result in a disk ending up full but I suppose if someone enables log_writers=file they already need to have some log rotation in place anyway. I wonder though if it could maybe enable some attacks where you issue lots of requests until the disk is full? I suppose many will have logging to file enabled.

@mattab any thoughts? Maybe we still need to check for tracker debug enabled.

@diosmosis commented on April 11th 2019 Member

I was a bit worried about the logging to file when an error occurs part that it could quickly result in a disk ending up full but I suppose if someone enables log_writers=file they already need to have some log rotation in place anyway. I wonder though if it could maybe enable some attacks where you issue lots of requests until the disk is full? I suppose many will have logging to file enabled.

Sounds like something worth protecting against... maybe by default we don't log to file for the tracker, and users have to enable it specifically. If logs are saved to the cloud, then space won't really be an issue.

@tsteur commented on April 11th 2019 Member

If logs are saved to the cloud, then space won't really be an issue.

It could be a cost problem though if sending eg to CloudWatch maybe. And usually the logs are still for some time on a local machine. Might actually need a different setting for it or so. Not sure how to best handle it.

@mattab commented on April 11th 2019 Member

Otherwise looks good if tests pass. I was a bit worried about the logging to file when an error occurs part that it could quickly result in a disk ending up full but I suppose if someone enables log_writers=file

maybe it makes sense to log thousands of lines in the log file, if the error occurs thousands of times... Question: when there is an error and it's logged in a file, is it logging one new line in the file (with the error message) or would it write possibly dozens or more lines for each error request?

@tsteur commented on April 11th 2019 Member

dozens.

You would still be able to cause a disk to fill. Eg on AWS you have like by default 8GB storage or so only.

@diosmosis commented on May 13th 2019 Member

Would it help in terms of space being written to only print debug logs if the error is legitimate and not, eg, a bad request? Ie, if someone puts in an invalid idsite, we don't consider it an error in matomo and don't print the debug logs, but if something unexpected happens in the tracker, we print the debug logs.

One other idea: think it would be a good idea to put a cap on the size of matomo.log? Ie, if the file is bigger than 1gb don't log (and maybe show a system check warning or something).

@tsteur commented on May 13th 2019 Member

Would it help in terms of space being written to only print debug logs if the error is legitimate and not, eg, a bad request?

that sounds good I reckon.

One other idea: think it would be a good idea to put a cap on the size of matomo.log? Ie, if the file is bigger than 1gb don't log (and maybe show a system check warning or something).

Could have this as a configuration in config.ini.php maybe. By default would maybe not limit though or set it to like 10GB. Although 10GB can be created very quickly (we've seen log files in the past with > 100GB). I would maybe not really limit but not sure, it could be useful. @mattab any thoughts?

@diosmosis commented on May 13th 2019 Member

I think a limit would be ok, since in most cases someone will set up log rotation, so the file shouldn't end up being enormous. And anyone who doesn't set up log rotation but enables file logging is just asking for trouble in the long run, since it will eventually get huge...

@tsteur commented on July 17th 2019 Member

@diosmosis there are various tests failing eg see https://travis-ci.org/matomo-org/matomo/jobs/530151402#L815 where it says a debug method isn't there but when I debug this manually in PHPStorm it all works. Might be just a matter of restarting the tests. It says:

PHP Fatal error:  Call to a member function debug() on null in /home/travis/build/matomo-org/matomo/core/Tracker.php on line 68
Fatal error: Call to a member function debug() on null in /home/travis/build/matomo-org/matomo/core/Tracker.php on line 68

There are also some tests failing here: https://travis-ci.org/matomo-org/matomo/jobs/530151401#L812

Otherwise works nicely for me.

@tsteur commented on September 30th 2019 Member

@diosmosis I think there are still some failing tests: https://travis-ci.org/matomo-org/matomo/jobs/586324829#L818

This Pull Request was closed on October 1st 2019
Powered by GitHub Issue Mirror