426463 - Adding logging support for bugzilla using log4perl

Status: RESOLVED DUPLICATE of bug 1437646

(bugzilla.mozilla.org :: General, enhancement, P1)

Description

[Noura Elhawary]

User-Agent:       Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.8.0.9) Gecko/20070209 Fedora/1.5.0.9-3.fc6 Firefox/1.5.0.9 pango-text
Build Identifier: 

adding logging support to bugzilla can help monitor bugzilla's performance in specific areas of the code and track down the bottlenecks. log4perl can be a very helpful tool to perform that.  I know Max mentioned that adding logging is not something that is needed now , but I thought I would submit the patch for that anyway maybe it can be helpful for others or might be needed later :)

Noura

Reproducible: Always

Comment 1

[Noura Elhawary]

Attachment: v1 for adding logging to bugzilla code using log4perl module

Hi,

attached is a patch that adds logging to bugzilla using log4perl module. The good thing about that patch is that logging can be turned on and off, using param log4perl_config that holds the log4perl configuration, is that param is left empty then logging will be turned off otherwise it will be turned on. logging messages can be spreaded all over the bugzilla code i only applied it to few places but it can be added to others places including the WebService Interface. each page logging will have START logging record and END logging recod with Time spent to execute, logging will be recorded in /tmp/bz.log. Please take a look when you can, I hope it is helpful.

Noura

Comment 2

[Frédéric Buclin]

Comment on attachment 313018 [details] [diff] [review]
v1 for adding logging to bugzilla code using log4perl module 

>Index: Bugzilla.pm

>+use Log::Log4perl;
>+use Log::Log4perl::MDC;

This makes this module mandatory, and many people don't have it, like me. I don't want to make Bugzilla depend on another mandatory module.

Also, I'm not a fan of tracking everything. Writing each action to a log file is going to slow down Bugzilla a lot AFAIK. And if you really want to do this, this should be done in a central way which doesn't require to edit so many files IMO.

Comment 3

[Max Kanat-Alexander]

This is cool, but we don't have any user requests for anything like this, so it's not a high priority at this time.

Comment 4

[Jeff Fearn 🐞]

Is the right way to do this to:

1: Use the features ... feature to see if Log4Perl is installed (add to optional deps)
2: Modify Bugzilla::Error::_throw_error to log if the Log4Perl feature is enabled
3: Modify Bugzilla::Template::process to log start/end of templates if a (new?) parameter is set and Log4Perl feature is enabled

Comment 5

[Frédéric Buclin]

IMO, this bug is WONTFIX. Noura said this module would be useful for debugging. But in a production environment, you don't want it, because logging everything would make things slower. And in a dev environment, each developer has its favorite debug module already, such as Devel::NYTProf.

If you want to track admin changes, we already log them in the audit table. If you want to collect requests, your web server already logs them. And from a privacy point of view, you don't want to log everything, especially URLs which may contain sensitive data such as the API token.

Comment 6

[Jeff Fearn 🐞]

(In reply to Frédéric Buclin from comment #5)
> IMO, this bug is WONTFIX. Noura said this module would be useful for
> debugging.

And it is, but it's also useful for production, which is why we have had it running there for a few years.

> But in a production environment, you don't want it, because
> logging everything would make things slower.

Then you'd not install the Log4Perl module on your production environment and it wouldn't do anything. In our experience the performance impact on a very busy site is minimal.

> And in a dev environment, each
> developer has its favorite debug module already, such as Devel::NYTProf.

Yeah but it's nice when your QE, Performance, Stage, & production environments can all report significant  data to your centralized logging service in the "right" format.

> If you want to track admin changes, we already log them in the audit table.
> If you want to collect requests, your web server already logs them. And from
> a privacy point of view, you don't want to log everything, especially URLs
> which may contain sensitive data such as the API token.

It's simply not the same quality of data and recording sensitive data would be a huge security issue.

Comment 7

[Thorsten Schöning]

(In reply to Frédéric Buclin from comment #5)
> IMO, this bug is WONTFIX.

No, this should have been included for a long time already, especially because of problems in production use.

> Noura said this module would be useful for
> debugging. But in a production environment, you don't want it

Sorry, but this is just wrong and I can't believe that you are using and referring to software with very capable logging facilities like any modern web server, like the OS itself and such and are on the other side voting against such logging facilities in your own software. :-) The whole world is capable of logging in its software or at least sees not beeing able to do so as problem which needs to be fixed.

> , because
> logging everything would make things slower.

And that's the good part about modern logging facilities and log4perl: If you don't want to use them, don't activate them. The overhead of ignored logging statements is a cost most of the world happily pays, because it simply doesn't matter that much. There are only very few exceptions where one needs to think about performance, e.g. when iterating over large lists and such, while logging/not logging on each and every element. But such things can always be optimized later. What do you think how many web servers just log all requests, simply because it's default behavior and nobody complains about performance, because it's just fast enough?

> And in a dev environment, each
> developer has its favorite debug module already, such as Devel::NYTProf.

But not only devs have problems getting or keeping Bugzilla running.
 
> If you want to track admin changes, we already log them in the audit table.
> If you want to collect requests, your web server already logs them.

What do the current Bugzilla admins do whenever there's any problem with Bugzilla because of e.g. upgraded Perl modules, because of changed setup and things don't work as expected? There's currently no admin friendly way to provide at least some data to track what is going on within Bugzilla, where mails are generated the way there are or which auth is used in which order because of which data, which templates are used from which directory because of wrongly named files in custom skins or templates or whatever. All such problems are VERY time consuming to find on a production system because it simply lacks useful logging.

> And from
> a privacy point of view, you don't want to log everything, especially URLs
> which may contain sensitive data such as the API token.

But that is not your decision, can be addressed by not logging all the data while still logging some useful parts of it and is missing the point, that one doesn't need to log everything all the time, but can simply activate logging in case of problems, delete files afterwards and if used right, is even capable to only activate logging for some special loggers for those parts of Bugzilla one is interested in.

Some minutes ago from the support mailing list and the reason why I searched for this bug:

> Would be helpful if there where a log file where i could debug and see what bugzilla received from the webinterface. 
> Isnt there anything like that yet ?

In my point of view, logging is one of the most basic things in any software. What do you do if your OS is not running, if Apache is not serving as expected and such? You look at log files. Know one of the main args against SystemD? No clear text logging... :-) And all your concerns can easily be addressed using proper configuration of log4perl.

So please, don't just close this bug, but instead provide some resources on this very basic topic.

Comment 8

[Dylan Hardison [:dylan] (he/him)]

Can you get this into shape in time for a 6.0 release?

1) logging should guarded by an optional feature: 'logging'.

You add these to the Makefile.PL, around here: https://github.com/bugzilla/bugzilla/blob/master/Makefile.PL#L90
Check for features using Bugzilla->has_feature() or Bugzilla->feature(). The later also loads the code...
I prefer loading the code explicitely as it helps my IDE figure out things:

So something like:
if (Bugzilla->has_feature('logging')) {
    require Log4Perl::Stuff;
}


2) LOG4PERL_DEFAULT_CONFIG has no reason to be in constants. it should be a file-scoped lexical in the Admin.pm file.

If the configured log4perl configuration causes an exception, it must die.. given the next two points

3) logging needs to be turned on as early in the process as possible. Right now there are three places it would need to go:

 i) mod_perl.pl (when mod_perl starts) https://github.com/bugzilla/bugzilla/blob/master/mod_perl.pl#L115
 ii) app.psgi (when plack starts) https://github.com/bugzilla/bugzilla/blob/master/app.psgi#L73
 iii) at the end of Bugzilla.pm if CGI (but not for plack or mod_perl)

4) if the configuration would cause an exception, it should be rejected. You can write a checker sub for this,
like https://github.com/bugzilla/bugzilla/blob/master/Bugzilla/Config/MTA.pm#L26

5) If the runtime checks are a performance problem for some people, we can define a constant based on an %ENV,
use constant DISABLE_LOGGING => $ENV{BUGZILLA_DISABLE_LOGGING}
and wrap all the feature-checked code with unless (DISABLE_LOGGING) { ... } which will be removed at compile time
and have no possible runtime penalty. I don't think we'll need to do this however.

Comment 9

[Thorsten Schöning]

I've added a reference to bug 1250936, because I'm currently facing that again and it's a good example on the benefits of the logging patch provided here: It would change ThrowTemplateError in a way that I would be able to see the actual error, which is currently not the case, because Apache httpd only logs the first some lines of output HTML in its error log.

Comment 10

[Jeff Fearn 🐞]

Hi Dylan, possibly :) It depends on how things pan out with our Bugzilla 5 upgrade.

Comment 11

[Dylan Hardison [:dylan] (he/him)]

This got fixed in bug 1437646