Commits
-------
cdf4b6a Checked log levels
a45d3ee Reverted last commit
529381b ControllerNotFound: Changed log level from info to error. Also moved throw exception code block up, to prevent the message from beeing logged multiple times.
7c29e88 Changed log level of "Matched route ..." message from info to debug
dca09fd Changed log level of "Using Controller ..." message from info to debug
Discussion
----------
Log levels
Just wanted to ask if the log level INFO is still correct for these messages?
As there are only four log levels left (DEBUG, INFO, WARNING, ERROR), DEBUG might be the more appropriate level for these messages now.
Let me give an example: An application is logging user actions (maybe to database) in order to assure comprehensibility, e. g. "User %s deleted post %d", "User %s written a message to user %s". These are not warnings of course, so the only suitable log level is INFO.
But they will be thrown together with these very common (at least two per request?) "Using controller..." and "Matched route..." messages when choosing INFO as log level.
---------------------------------------------------------------------------
by Seldaek at 2011/05/24 07:13:18 -0700
Agreed, this stuff is framework debug information.
---------------------------------------------------------------------------
by fabpot at 2011/05/24 08:53:24 -0700
Why do you want to change these two specific ones? The framework uses the INFO level at other places too. Is it a good idea to say that the framework only logs with DEBUG?
---------------------------------------------------------------------------
by stof at 2011/05/24 09:12:53 -0700
Doctrine logs at the INFO level too and I think it is useful to keep it as INFO. Being able to see the queries without having all DEBUG messages of the event dispatcher and security components is useful IMO.
---------------------------------------------------------------------------
by Seldaek at 2011/05/25 02:30:24 -0700
Yeah, that's true, maybe we just need to reintroduce (again, meh:) NOTICE between INFO and WARNING.
@kaiwa Of course the other way could be that you just add your DB handler to the app logger stack. That could be done in a onCoreRequest listener or such, basically you'd have to call `->pushHandler($yourDBHandler)` on the `monolog.logger.app` service. That way your messages will flow to it, but it won't receive noise from the framework stuff since those log on monolog.logger.request and other log channels.
---------------------------------------------------------------------------
by fabpot at 2011/05/25 02:48:26 -0700
@Seldaek: I don't think we need another level. We just need to come up with a standard rules about the usage of each level. Adapted from log4j:
* ERROR: Other runtime errors or unexpected conditions.
* WARN: Use of deprecated APIs, poor use of API, 'almost' errors, other runtime that are undesirable or unexpected, but not necessarily "wrong" (unable to write to the profiler DB, ).
* INFO: Interesting runtime events (security infos like the fact the user is logged-in or not, SQL logs, ...).
* DEBUG: Detailed information on the flow through the system (route match, security flow infos like the fact that a token was found or that remember-me cookie is found, ...).
What do you think?
---------------------------------------------------------------------------
by stloyd at 2011/05/25 02:53:38 -0700
+1 for this standard (also this PR can be merged then), but we should review code for other "wrong" log levels usage (if everyone accept this standard)
---------------------------------------------------------------------------
by fabpot at 2011/05/25 02:55:07 -0700
I won't merge this PR before all occurrences of the logger calls have been reviewed carefully and changed to the right level.
---------------------------------------------------------------------------
by kaiwa at 2011/05/25 02:58:44 -0700
@fabpot: Just noticed these two occurring for every request in my log file. You are right, there are other places where this changes must be applied if we will change the log level.
@stof: Hmm, i see. It is not possible to set the logger separately for each bundle, is it? That maybe would solve the problem. If somebody is interested in seeing the queries, he could set the log handler level to DEBUG for doctrine bundle, but still use INFO for the framwork itself. Plus he could even define a different output file or a completely different handler.
I'm not sure if something like that is possible already (?) or realizable at all... just came into my mind.
---------------------------------------------------------------------------
by Seldaek at 2011/05/25 03:01:07 -0700
Just FYI, from Monolog\Logger (which has CRITICAL and ALERT):
* Debug messages
const DEBUG = 100;
* Messages you usually don't want to see
const INFO = 200;
* Exceptional occurences that are not errors
* This is typically the logging level you want to use
const WARNING = 300;
* Errors
const ERROR = 400;
* Critical conditions (component unavailable, etc.)
const CRITICAL = 500;
* Action must be taken immediately (entire service down)
* Should trigger alert by sms, email, etc.
const ALERT = 550;
The values kind of match http error codes too, 4xx are expected errors that are not really important (404s etc) and 5xx are server errors that you'd better fix ASAP. I'm ok with the descriptions, but I think alert and critical should be included too. I'll probably update Monolog docblocks to match whatever ends up in the docs.
---------------------------------------------------------------------------
by Seldaek at 2011/05/25 03:03:21 -0700
@kaiwa you can do a lot, but not from the default monolog configuration entry, I'm not sure if we can really make that fully configurable without having a giant config mess. Please refer to my [comment above](https://github.com/symfony/symfony/pull/1073#issuecomment-1234316) to see how you could solve it. Maybe @fabpot has an idea how to make this more usable though.
---------------------------------------------------------------------------
by stof at 2011/05/25 03:19:43 -0700
@Seldaek the issue is that the different logging channels are only know in the compiler pass, not in the DI extension. So changing the level in the extension is really hard IMO.
Thus, the handlers are shared between the different logging channels (needed to open the log file only once for instance, or to send a single mail instead of one per channel) and the level is handled in the handlers, not the logger.
I'm +1 for the standard, by adding the distinction between 400 and 500 status calls using ERROR and CRITICAL (which is already the case in the code).
@kaiwa do you have time to review the calls to the logger between DEBUG and INFO or do you prefer I do it ? For instance, the Security component currently logs all message at DEBUG level and some of them should be INFO.
---------------------------------------------------------------------------
by kaiwa at 2011/05/25 04:31:04 -0700
@stof ok i'll do that
---------------------------------------------------------------------------
by kaiwa at 2011/05/25 12:22:51 -0700
Need some help :) I came across `ControllerNameParser::handleControllerNotFoundException()` which leads to redundant log messages currently:
>[2011-05-25 20:53:16] request.INFO: Unable to find controller "AppBaseBundle:Blog" - class "App\BaseBundle\Controller\BlogController" does not exist.
>[2011-05-25 20:53:16] request.ERROR: InvalidArgumentException: Unable to find controller "AppBaseBundle:Blog" - class "App\BaseBundle\Controller\BlogController" does not exist. (uncaught exception) at /home/ruth/symfony3/src/Symfony/Bundle/FrameworkBundle/Controller/ControllerNameParser.php line 87
Is it necessary to call `$this->logger->info($log);` if the InvalidArgumentException will be logged anyway?
---------------------------------------------------------------------------
by stof at 2011/05/25 12:39:22 -0700
Well, the issue is that the ControllerNameParser logs messages and then uses them to throw an exception. I guess the logging call should be removed as it is redundant with the one of the ExceptionListener. @fabpot thoughts ?
---------------------------------------------------------------------------
by kaiwa at 2011/05/27 11:39:25 -0700
I checked all debug, info and log calls. Sometimes it is hard to distinguish between the levels, so it would be great if someone reviews @cdf4b6a. @stof, maybe you want to take a look?
---------------------------------------------------------------------------
by kaiwa at 2011/05/31 12:52:07 -0700
@stof, thanks for your comments. I added some replies above, please let me know your suggestions.
---------------------------------------------------------------------------
by stof at 2011/05/31 14:04:22 -0700
@kaiwa As I said before, all the security logging calls should be DEBUG (most of them) or INFO (the one syaing that authentication succeeded for instance), but not WARN or ERROR as the exception don't go outside the firewall.
