Replace some usages of Common::printDebug w/ use of logger #13968

diosmosis · 2019-01-17T00:19:17Z

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

sgiehl

There are still a lot usage of Common::printDebug, guess we need to replace them step by step.
Changes look good and seem to work

diosmosis · 2019-02-25T15:35:37Z

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

diosmosis · 2019-02-26T04:14:09Z

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

tsteur · 2019-02-26T17:48:29Z

core/Common.php

-                }
-            }
+        $logger = StaticContainer::get('Psr\Log\LoggerInterface');
+        if (is_array($info) || is_object($info)) {


is the second is_object still needed?

Huh, looks like it was never needed...

tsteur · 2019-02-26T17:49:53Z

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 · 2019-02-26T18:03:18Z

@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 · 2019-02-26T22:45:28Z

@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 · 2019-02-26T22:54:55Z

@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 · 2019-02-26T23:23:06Z

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 · 2019-02-26T23:26:23Z

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 · 2019-02-26T23:37:41Z

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 · 2019-02-26T23:47:25Z

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 · 2019-02-26T23:54:05Z

👍

tsteur · 2019-04-11T01:44:49Z

@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 · 2019-04-11T02:38:09Z

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 · 2019-04-11T02:40:50Z

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 · 2019-04-11T04:31:49Z

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 · 2019-04-11T04:40:46Z

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 · 2019-05-13T03:23:26Z

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 · 2019-05-13T22:29:11Z

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 · 2019-05-13T22:33:05Z

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 · 2019-07-17T04:44:35Z

@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 · 2019-09-30T20:32:47Z

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

diosmosis added 3 commits January 15, 2019 18:40

Start refactoring Common::printDebug().

50b2174

Make tracker debug statement error log.

17b882f

Remove logger removal for tracker.

f4c1c50

diosmosis added the Needs Review PRs that need a code review label Jan 17, 2019

diosmosis added this to the 3.9.0 milestone Jan 17, 2019

sgiehl approved these changes Feb 25, 2019

View reviewed changes

tsteur reviewed Feb 26, 2019

View reviewed changes

mattab modified the milestones: 3.9.0, 3.10.0 Mar 18, 2019

Merge branch '3.x-dev' into tracker-logging

4d2efc2

diosmosis removed this from the 3.10.0 milestone May 15, 2019

diosmosis added this to the 3.11.0 milestone May 15, 2019

mattab modified the milestones: 3.11.0, 3.12.0 Jul 23, 2019

diosmosis added 4 commits August 4, 2019 09:57

Merge branch '3.x-dev' into tracker-logging

6afe272

Fix test failure.

5540ad7

Add two more parent constructor calls.

4a94882

Merge branch '3.x-dev' into tracker-logging

00a88aa

diosmosis added 2 commits September 30, 2019 18:36

Merge branch '3.x-dev' into tracker-logging

77610be

Fix failing test

fd48f7d

diosmosis merged commit 42a62a2 into 3.x-dev Oct 1, 2019

diosmosis deleted the tracker-logging branch October 1, 2019 03:23

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Replace some usages of Common::printDebug w/ use of logger #13968

Replace some usages of Common::printDebug w/ use of logger #13968

diosmosis commented Jan 17, 2019

sgiehl left a comment

diosmosis commented Feb 25, 2019

diosmosis commented Feb 26, 2019

tsteur Feb 26, 2019

diosmosis Feb 26, 2019

tsteur commented Feb 26, 2019

diosmosis commented Feb 26, 2019

tsteur commented Feb 26, 2019

diosmosis commented Feb 26, 2019

tsteur commented Feb 26, 2019

diosmosis commented Feb 26, 2019

tsteur commented Feb 26, 2019

diosmosis commented Feb 26, 2019

tsteur commented Feb 26, 2019

tsteur commented Apr 11, 2019

diosmosis commented Apr 11, 2019

tsteur commented Apr 11, 2019

mattab commented Apr 11, 2019

tsteur commented Apr 11, 2019

diosmosis commented May 13, 2019

tsteur commented May 13, 2019

diosmosis commented May 13, 2019

tsteur commented Jul 17, 2019

tsteur commented Sep 30, 2019

Navigation Menu

Replace some usages of Common::printDebug w/ use of logger #13968

Replace some usages of Common::printDebug w/ use of logger #13968

Conversation

diosmosis commented Jan 17, 2019

sgiehl left a comment

Choose a reason for hiding this comment

diosmosis commented Feb 25, 2019

diosmosis commented Feb 26, 2019

tsteur Feb 26, 2019

Choose a reason for hiding this comment

diosmosis Feb 26, 2019

Choose a reason for hiding this comment

tsteur commented Feb 26, 2019

diosmosis commented Feb 26, 2019

tsteur commented Feb 26, 2019

diosmosis commented Feb 26, 2019

tsteur commented Feb 26, 2019

diosmosis commented Feb 26, 2019

tsteur commented Feb 26, 2019

diosmosis commented Feb 26, 2019

tsteur commented Feb 26, 2019

tsteur commented Apr 11, 2019

diosmosis commented Apr 11, 2019

tsteur commented Apr 11, 2019

mattab commented Apr 11, 2019

tsteur commented Apr 11, 2019

diosmosis commented May 13, 2019

tsteur commented May 13, 2019

diosmosis commented May 13, 2019

tsteur commented Jul 17, 2019

tsteur commented Sep 30, 2019