2

Consider the following scenario:

I am writing a Dispatcher Servlet that delegates processing to various handlers depending on the request URL; the handler objects having previously registered themselves for URL patterns, pretty much as Servlets register themselves in web.xml.

When a Handler registers or unregisters itself for a pattern, I want to log a line that includes the action and pattern; and also the current mappings, so that when a subsequent request processing logs a warning that a request was not processed I can go back in the logs and find out the mappings.

The question is how to ensure that lines logged by registerUrlPattern/unregisterUrlPattern actually appear in the log file:

  • It seems to me that these methods should log the mapping changes at INFO level, since it is additional INFO being logged. But the logger's level is WARN so that will not work. The logger get many other messages at INFO level so it is not possible to change its level to INFO in production, except for troubleshooting.

  • I could log it at WARN level, but qa/usability/customer does not like such warnings to appear.

I can think of the following alternatives:

  • Change the Logger's level to INFO when logging these lines, possibly by adding a forceInfo method in my Logger (which wraps a standard log4j type logger)

  • Use a different Logger for these methods and set its level to INFO

  • Log at warning level but change the language to indicate that it is not something to be worried about

1
  • I would not log at the warning level. Your first one should work fine if you have a tool for mining logs. If you include something unique in your log line to indicate its content, then a simple grep search on your log file would probably suffice. Jul 11, 2013 at 1:38

3 Answers 3

7

So, you need different treshold within the same class. I think you use a different logger corresponding to a specific name. You can thus set the log level to INFO for this specific Logger in DispatchServlet class.

For me, the benefits would be:

  • the possibility to specificly reduce the treshold to INFO as you required (the goal).
  • if one day you realize that your specific logs become too verbose and finally useless because the functionnality is 100% stable and doesn't cause any issue, you still can reduce the treshold by configuration and without impacting the rest of the logs. Logging in WARNING level or do something based on forcedLog would imply you to modify the sources for such a purpose.

The only CON I see is that it might be "surprising" but a correct documentation solves everything.

For example in your log4j.xml file, you could have:

<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">
    <!-- general application log -->
    <appender name="MyLogFileAppender" class="org.apache.log4j.FileAppender">
        <param name="File" value="mylog.log" />
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d{yyyy MM dd - HH:mm:ss,SSS} %-5p %t [%-40.40c] %x - %m%n"/>
        </layout>
    </appender>
    <logger name="DispatchServletSpecific">
        <level value="INFO" />
        <appender-ref ref="MyLogFileAppender" />
    </logger>
    <root>
         <level value="WARNING" />
         <appender-ref ref="MyLogFileAppender" />
    </root>
</log4j:configuration>

And in the Java code you create a specific Logger

Logger specificLogger = Logger.getLogger("DispatchServletSpecific");

This way the log treshold should be set to INFO while the rest of your app should be log only WARNING logs. Hope it helps.

3
  • The problem is that I don't want to set DispatcherServlet's log level to INFO -- that would make it generate lot more in the log files that I don't want it to Jul 11, 2013 at 16:21
  • @HemalPandya see my edited answer. Jul 11, 2013 at 17:18
  • Yes, a different logger is what I considered as one of the options. So you are saying you prefer that over changing the log level for those specific calls? Can you please elaborate why? I am trying to identify the pros and cons of two approaches. Jul 11, 2013 at 20:06
2

Change the Logger's level to INFO when logging these lines, possibly by adding a forceInfo method in my Logger (which wraps a standard log4j type logger)

At some point down the line you will probably consider the register/unregister behaviour reliable enough that you don't want to log it any more, and you only want to see 'proper' warnings. At this point you'll have no option but to go and change the code.

Use a different Logger for these methods and set its level to INFO

Yep, do this. It gives you the fine-grained control that you need in this scenario.

Log at warning level but change the language to indicate that it is not something to be worried about

Don't do this. Your users/QA don't want it, ant the event isn't a warning, so don't make it one. Also, you again have to change the code in order to disable logging these events.

2
  • Thank you for a thoughtful answer. I think your first para above applies to my first option but you pasted wrong. I am logging this to verify that my clients are registering properly, over which have no control and may never be able to decide that I want to change the level. I think I will go with using a separate logger. Jul 13, 2013 at 1:01
  • You were right about the first quote, fixed it. Jul 13, 2013 at 8:12
0

Instead of trying to force a message containing the data you want available when another message is logged, you should use Log4J's Thread Context capability to add the data to the other message. That way, if the error message is issued, it carries along the data you want logged. So, for example, instead of:

logger.ForceInfoOutputEvenThoughBelowLoggingLevel("Hey, I'm going to be processing record " + recordNumber + ", so if an error happens, you'll know what I'm doing!");
...
logger.Error("OMG!")

which would presumably log:

INFO Hey, I'm going to be processing record 42, so if an error happens, you'll know what I'm doing!
ERROR OMG!

you'd do this instead:

ThreadContext.put("recordNumber", recordNumber);
...
logger.Error("OMG!")

which, with %x or %X in your Log4J config's layout definition, would log:

ERROR recordNumber=42 OMG!

The point is to augment the error message with useful data, rather than to force another message into the log. This has lots of benefits, including the fact that you can augment any message issued by any code, without having to modify that code, even if you don't have it's source.

3
  • How would I Use Thread Context to force output of a line logged at lower then current applicable level? Can you please elaborate? Jul 13, 2013 at 0:57
  • Edited to add details. Jul 13, 2013 at 14:06
  • I suspect you don't get the point of my question. I don't want to log the INFO line if/when the ERROR line is logged. I want to always log it. Jul 13, 2013 at 23:50

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge that you have read and understand our privacy policy and code of conduct.

Not the answer you're looking for? Browse other questions tagged or ask your own question.