Hello Yoram, Thanks for posting the status messages. I am having a hard time reproducing these messages based on the configuration that you posted previously. Could you post the entire output, and your complete configuration file? Also, could you tell me which version of logback are you using? Cheers, Sébastien Yoram Forscher wrote:

Thanks for the prompt reply. I changed the configuration file as you suggested and invoked LoggerStatusPrinter.printStatusInDefaultContext() after the logging request. I received a lot of output and I included below the four lines that indicated an error.

The filter still does not give me the result that I'm looking for. I appreciate any help you can give me.

-- Yoram

|-ERROR in ch.qos.logback.core.joran.action.NestedComponentIA - No class name attribute in <evaluator> |-ERROR in ch.qos.logback.core.joran.spi.InterpretationContext@1762fc7 - no applicable action for <expression>, current pattern is [/configuration/appender/filter/evaluator/expression] |-ERROR in ch.qos.logback.core.joran.spi.InterpretationContext@1762fc7 - no applicable action for <OnMatch>, current pattern is [/configuration/appender/filter/OnMatch] |-ERROR in ch.qos.logback.core.filter.EvaluatorFilter@3aef16 - No evaluator set for filter null |

-----Original Message----- From: Ceki Gülcü [mailto:listid@qos.ch] Sent: Wednesday, December 20, 2006 3:46 PM To: logback users list Subject: Re: [logback-user] How To Use Filters

Yoram,

Thanks for using logback.

You can instruct logback-classic to tell you to print its internal status with the following call:

LoggerStatusPrinter.printStatusInDefaultContext();

This will print logback's internal error messages on the console.

You can achieve a similar affect in configuration files by setting the debug attribute of the configuration element to true. For example:

<configuration debug="true"> <--- this line <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <layout class="ch.qos.logback.classic.PatternLayout"> <pattern> %d{HH:mm:ss.SSS} [%thread] %-5level %logger{32} - %msg%n </pattern> </layout> </appender> <root> <level value="DEBUG" /> <appender-ref ref="STDOUT" /> </root> </configuration>

When logback is done configuring itself using the above config file, it will dump its internal status on the console.

Anyway, I'd first try invoking LoggerStatusPrinter's printStatusInDefaultContext() after the

logger.debug(pcMarker, "Cnfiguration...")

call and see what logback tells you.

My guess is that it will complain about exceptions thrown by the expression evaluator because marker is null. Try changing the expressions to

<evaluator name="myEval"> <expression>(marker != null) && (marker.contains("printConfiguration"))</expression> </evaluator> <OnMismatch>NEUTRAL</OnMismatch> <OnMatch>DENY</OnMatch>

The && combination represents Java's expression for logical AND, that is '&&', which you cannot write as is in XML files.

Please let us know how it goes.

At 08:18 PM 12/20/2006, Yoram Forscher wrote:

...

After reading chapter 6, "Filter Chains," I tried to use some filters myself with no success. My configuration file contains the following:

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <filter class="ch.qos.logback.core.filter.EvaluatorFilter"> <evaluator name="myEval">

<expression>marker.getName().equals("printConfiguration")</expression> </evaluator> <OnMismatch>NEUTRAL</OnMismatch> <OnMatch>DENY</OnMatch> </filter> <layout class="ch.qos.logback.classic.PatternLayout"> <param name="pattern" value="%d{ISO8601} %-5p [%c{40}] %m%n"/> </layout> </appender>

In my code I have the following: private Marker pcMarker = MarkerFactory.getMarker("printConfiguration"); ... logger.debug(pcMarker, "Configuration Information"); ...

I expect in that case that no output will be created, but it keeps printing it regardless of how I set it up. I also tried to change the expression to 'marker.contains("printConfiguration")' and change the OnMismatch and OnMatch both to DENY. Same result.

What am I doing wrong?

-- Sébastien Pennec sebastien@qos.ch Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch/

Hello Yoram, Happy new year to you :) I've searched for a while and still cannot reproduce the same status output with version 0.7.1. I've eventually tried with older versions, and found that version 0.5 of logback outputs _exactly_ the same lines that you included in your last email. Could you make really sure that you are using version 0.7.1 before we go into further investigations? You can check that by editing the pom.xml that is inside the jars. If you open the logback-core jar, you will find it in this directory: $LOGBACK_JAR/META-INF/maven/ch.qos.logback/logback-core/pom.xml At the beginning of the file, you should see these lines if you're using version 0.5: <parent> <artifactId>logback</artifactId> <groupId>ch.qos.logback</groupId> <version>0.5</version> </parent> and these if you're using version 0.7.1: <parent> <groupId>ch.qos.logback</groupId> <artifactId>logback-parent</artifactId> <version>0.7.1</version> </parent> Let me know what comes out... One more thing about the jars that you will need. If you want to use evaluation filters, you will need the Janino jar as well as the logback jars, since Janino is a logback dependency. You will find them at the Janino home page[1]. Cheers, Sébastien [1]http://www.janino.net/download.html#packages Yoram Forscher wrote:

Hi Sebastien,

Sorry for the long delay due to the holiday season. Here's the information that you requested: * The version of logback that I'm using is 0.7.1 * The full configuration file is:

<?xml version="1.0" encoding="UTF-8" ?> <configuration debug="true"> <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <filter class="ch.qos.logback.core.filter.EvaluatorFilter"> <evaluator name="myEval" > <expression> (marker != null) && (marker.contains("printConfiguration")) </expression> </evaluator> <OnMismatch>NEUTRAL</OnMismatch> <OnMatch>DENY</OnMatch> </filter>

<layout class="ch.qos.logback.classic.PatternLayout"> <param name="pattern" value="%d{ISO8601} %-5p [%c{40}] %m%n"/> </layout> </appender>

<root> <level value="debug"/> <appender-ref ref="STDOUT"/> </root>

<logger name="org.apache"> <level value="info"/> </logger>

</configuration>

* Even though I specified 'debug="true",' I did not get any debug output until I invoked LoggerStatusPrinter.printStatusInDefaultContext();

* The information output by the LoggerStatusPrinter is: |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender] |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT] |-INFO in ch.qos.logback.core.joran.action.NestedComponentIA - is dmmed applicable for /configuration/appender/filter |-INFO in ch.qos.logback.core.joran.action.NestedComponentIA - Pushing component <filter> on top of the object stack. |-INFO in ch.qos.logback.core.joran.action.NestedComponentIA - is dmmed applicable for /configuration/appender/filter/evaluator |-ERROR in ch.qos.logback.core.joran.action.NestedComponentIA - No class name attribute in <evaluator> |-ERROR in ch.qos.logback.core.joran.spi.InterpretationContext@5ff916 - no applicable action for <expression>, current pattern is [/configuration/appender/filter/evaluator/expression] |-ERROR in ch.qos.logback.core.joran.spi.InterpretationContext@5ff916 - no applicable action for <OnMatch>, current pattern is [/configuration/appender/filter/OnMatch] |-ERROR in ch.qos.logback.core.filter.EvaluatorFilter@da3772 - No evaluator set for filter null |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Popping appender named [STDOUT] from the object stack |-INFO in ch.qos.logback.classic.joran.action.LevelAction - root level set to DEBUG |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT to Logger[root] |-INFO in ch.qos.logback.classic.joran.action.LevelAction - org.apache level set to INFO |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.

* One more thing: My application runs as a Web Application under Tomcat and is also using Spring. The logback JAR files (classic and core) as well as alf4j-api JAR file are in WEB-INF/lib. The configuration file is in WEB-INF.

Thanks,

Yoram

-----Original Message----- From: Sebastien Pennec [mailto:sebastien@qos.ch] Sent: Friday, December 22, 2006 6:12 AM To: logback users list Subject: Re: [logback-user] How To Use Filters

Hello Yoram,

Thanks for posting the status messages.

I am having a hard time reproducing these messages based on the configuration that you posted previously. Could you post the entire output, and your complete configuration file?

Also, could you tell me which version of logback are you using?

Cheers,

Sébastien

Yoram Forscher wrote:

...

Thanks for the prompt reply. I changed the configuration file as you suggested and invoked LoggerStatusPrinter.printStatusInDefaultContext() after the logging request. I received a lot of output and I included below the four lines that indicated an error.

The filter still does not give me the result that I'm looking for. I appreciate any help you can give me.

-- Yoram

|-ERROR in ch.qos.logback.core.joran.action.NestedComponentIA - No class name attribute in <evaluator> |-ERROR in ch.qos.logback.core.joran.spi.InterpretationContext@1762fc7 - no applicable action for <expression>, current pattern is [/configuration/appender/filter/evaluator/expression] |-ERROR in ch.qos.logback.core.joran.spi.InterpretationContext@1762fc7 - no applicable action for <OnMatch>, current pattern is [/configuration/appender/filter/OnMatch] |-ERROR in ch.qos.logback.core.filter.EvaluatorFilter@3aef16 - No evaluator set for filter null |

-----Original Message----- From: Ceki Gülcü [mailto:listid@qos.ch] Sent: Wednesday, December 20, 2006 3:46 PM To: logback users list Subject: Re: [logback-user] How To Use Filters

Yoram,

Thanks for using logback.

You can instruct logback-classic to tell you to print its internal status with the following call:

LoggerStatusPrinter.printStatusInDefaultContext();

This will print logback's internal error messages on the console.

You can achieve a similar affect in configuration files by setting the debug attribute of the configuration element to true. For example:

<configuration debug="true"> <--- this line <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <layout class="ch.qos.logback.classic.PatternLayout"> <pattern> %d{HH:mm:ss.SSS} [%thread] %-5level %logger{32} - %msg%n </pattern> </layout> </appender> <root> <level value="DEBUG" /> <appender-ref ref="STDOUT" /> </root> </configuration>

When logback is done configuring itself using the above config file, it will dump its internal status on the console.

Anyway, I'd first try invoking LoggerStatusPrinter's printStatusInDefaultContext() after the

logger.debug(pcMarker, "Cnfiguration...")

call and see what logback tells you.

My guess is that it will complain about exceptions thrown by the expression evaluator because marker is null. Try changing the expressions to

<evaluator name="myEval"> <expression>(marker != null) && (marker.contains("printConfiguration"))</expression> </evaluator> <OnMismatch>NEUTRAL</OnMismatch> <OnMatch>DENY</OnMatch>

The && combination represents Java's expression for logical AND, that is '&&', which you cannot write as is in XML files.

Please let us know how it goes.

At 08:18 PM 12/20/2006, Yoram Forscher wrote:

...

After reading chapter 6, "Filter Chains," I tried to use some filters myself with no success. My configuration file contains the following:

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <filter class="ch.qos.logback.core.filter.EvaluatorFilter"> <evaluator name="myEval">

<expression>marker.getName().equals("printConfiguration")</expression> </evaluator> <OnMismatch>NEUTRAL</OnMismatch> <OnMatch>DENY</OnMatch> </filter> <layout class="ch.qos.logback.classic.PatternLayout"> <param name="pattern" value="%d{ISO8601} %-5p [%c{40}] %m%n"/> </layout> </appender>

In my code I have the following: private Marker pcMarker = MarkerFactory.getMarker("printConfiguration"); ... logger.debug(pcMarker, "Configuration Information"); ...

I expect in that case that no output will be created, but it keeps printing it regardless of how I set it up. I also tried to change the expression to 'marker.contains("printConfiguration")' and change the OnMismatch and OnMatch both to DENY. Same result.

What am I doing wrong?

-- Sébastien Pennec sebastien@qos.ch Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch/

Hi Yoram, Comments inline. At 07:52 PM 1/3/2007, Yoram Forscher wrote:

Hi Sebastien,

Happy New Year to you too and thanks for the prompt reply.

You were correct, of course. I was using a previous version of logback, because the IDE I'm using (Intellij) did not clear WEB-INF/lib before copying the JAR files, leaving the previous version there.

Now that I use the correct JAR files, the filters work correctly.

One new thing that I noticed, and I think it's a change from previous versions, is that when creating a context (LoggerFactory.getILoggerFactory()), this context is initialized with the default configuration which includes a console appender. In order to start from a clean slate I had to invoke shutdownAndReset() on the context before loading my own configuration. This is not documented, and frankly I think this behavior is incorrect.

We've been agonizing about the question of default configuration in the absence of a (default) configuration file for a very long time. We have recently succumbed to user demand and now initialize the context with a console appender in case no default configuration could be found. There are pros and cons to this approach. Many, including myself, consider that defaulting to the console, without any explicit action by the user, as desirable. However, in case configuration is performed explicitly at a later stage, one must make sure to call shutdownAndReset() on the logging context. This is unfortunately undocumented in the "Short Introduction". This omission should be considered a bug which we will fix for the next release. There is one case I can imagine where the current behavior might be troublesome. Assume that before the user can explicitly configure logback, some other component makes logging calls. In that case those logs will appear on the console instead of being lost. WDYT?

One last thing: what is the expected behavior of logger.isDebugEnabled(marker)?

The method isXXXEnabled(Marker) is part of the org.slf4j.Logger interface. The original idea was to allow the value returned by isDebugEnabled to depend on a marker value. However, it turns out that this is not possible in practice. Thus, in the current code of logback isDebugEnabled(Marker) simply delegates to isDebugEnabled().

Thanks for your help,

Thanks for your interest in logback,

Yoram

-- Ceki Gülcü Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch

At 09:54 PM 1/3/2007, Yoram Forscher wrote:

Hi Ceki,

I see your point regarding the default configuration and it makes a lot of sense to provide some basic logging capability even if the user neglects to configure. The requirement to invoke shutdownAndReset(), though, is IMHO not elegant and error prone. Maybe you can internally clear the configuration when the user invoked doConfigure()?

If we automatically called shutdownAndReset() every time a configurator was invoked, it would not be possible to do partial configurations. By partial configuration, I mean configuration of logback using multiple config files. However, we might add this functionality in the future if it comes up again.

Regarding logger.isXXXEnabled(marker), I thought it will give me the exact functionality that you mentioned, i.e., that it will depend on the marker value. When I used it I wanted to conditionally log some debug information that takes a lot of processing to generate. I did not want the overhead involved in generating this information if it will never be logged. When using log4j, I would put this kind of information at the TRACE level but this is not possible with logback. Do you see a good way to achieve this functionality?

I kind of see what you mean. However, could you give an example of "information which takes a lot of processing to generate"? Maybe you can use parameterized logging...

Thanks,

Yoram

-- Ceki Gülcü Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch

Hello, In case of dropped events, that is when the filter returns DENY and drops the logging request, the LevelFilter performs significantly better than the expression-based (Janino) filter. However, in case the event is logged, that is when the filter accepts the event it is sent to an appender, the impact of the filter is negligible compared to the cost incurred in the appender. Here are some figures: It takes about 21'000 nanoseconds to write to a file using FileAppender regardless of the filter type used. However, when the filter drops events, it takes about 1'400 nanos to decide to drop the events whereas it takes 2'300 nanos with the expression-based (Janino) filter. HTH, Ceki for Sébastien ps: The LevelFilter was only recently added and is available only via our subversion repository. At 06:11 PM 12/21/2006, you wrote:

Hello Eric,

Thanks for using logback :)

Appender threshold are not available in logback because the Appender class is in the core module, where there is no concept of level. However, like you correctly mentionned, the use of a filter can provide the functionnality that the threshold offers.

We are right in the process of testing filter performance. If the use of expression based filters is not satisfying in terms of speed, we will add a dedicated filter to cover this use case.

You can expect a more precised and detailled answer within the next 24 hours, once I've investigated further.

Cheers,

Sébastien

Eric Yung wrote:

...

Hi, I have migrated from log4j to slf4j and logback. I have one question for the appender setting. In log4j, you can set the threshold of an appender so that only a certain level of log messages will be logged by that appender. But in logback, I can only achieve this behavior by using a expression filter. I would like to know the performance figure about that filter. If the expression filter takes much longer than a dedicated log level filter, I would like to see a simple log level filter be included in logback.

Thanks, Eric _______________________________________________ Logback-user mailing list Logback-user@qos.ch http://qos.ch/mailman/listinfo/logback-user

-- Sébastien Pennec sebastien@qos.ch

Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch/ _______________________________________________ Logback-user mailing list Logback-user@qos.ch http://qos.ch/mailman/listinfo/logback-user

-- Ceki Gülcü Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch

Dear Sébastien, Thanks for you help. I will check out the new code to try later. Thanks, Eric Sebastien Pennec wrote:

Hello Eric,

I've run several tests this morning about filter performance.

Issuing a log request takes around 1950 nanoseconds. Adding an EvaluatorFilter to check the level and accept of deny the request based on its level makes the previous figure go up to 2450 nanoseconds.

I've tried to add a LevelFilter to the test. It takes three options: level, onMatch and onMismatch. Running the same tests with the dedicated filter takes around 2050 nanoseconds per requests.

EvaluatorFilters are great to provide highly flexible filtering possibilities, but they are not on par with a specialized class that would filter events based on a single criteria. However, 2450 nanoseconds is not a bad value as such, it still lets you log more that 400'000 requests every seconds. Of course, these figures will depend on other factors, such as the Appender and the Layout you wish to use.

The LevelFilter will is now available in the svn, so if you want to test it on your side, feel free to checkout a copy and let us know about your experience :)

Here is a sample configuration that uses LevelFilter:

<configuration debug="true">

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <filter class="ch.qos.logback.classic.filter.LevelFilter"> <level>INFO</level> <OnMismatch>DENY</OnMismatch> <OnMatch>ACCEPT</OnMatch> </filter> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern>%-4relative [%thread] %-5level - %msg%n</Pattern> </layout> </appender>

<root> <level value="debug" /> <appender-ref ref="STDOUT" /> </root> </configuration>

Cheers,

Sébastien

Eric Yung wrote:

...

Hi,

I have migrated from log4j to slf4j and logback. I have one question for the appender setting. In log4j, you can set the threshold of an appender so that only a certain level of log messages will be logged by that appender. But in logback, I can only achieve this behavior by using a expression filter. I would like to know the performance figure about that filter. If the expression filter takes much longer than a dedicated log level filter, I would like to see a simple log level filter be included in logback.

Thanks, Eric

_______________________________________________ Logback-user mailing list Logback-user@qos.ch http://qos.ch/mailman/listinfo/logback-user