Re: Logging using log4j filters

[Bengt Rodehav <be...@rodehav.com>]

FYI Guillaume,

I continued this discussion on the OPS4J mailing list:

http://www.mail-archive.com/general@lists.ops4j.org/msg12287.html

/Bengt

2012/1/30 Bengt Rodehav <be...@rodehav.com>

> A moment ago I thought I had solved the problem since I noticed that I had
> written "bunde.name:..." instead of "bundle.name:...". That would have
> explained everything but unfortunately I still can't get it to work after
> having corrected my spelling.
>
> Using the org.apache.camel logger won't help me here. Although my example
> uses "bundle.name", I intend to use the "camelContext" MDC in production.
> We have dozens of camel routes that we want to put in different log files
> depending on which camel context we need to debug. Thus the logger (i e the
> package name) is of no help. MDC is needed to get this to work.
>
> I see your point now that the layout isn't taken into account. Actually I
> had not understood that the string "bundle.name:org.apache.camel.camel-core"
> had to be found in the log message. I thought it was a special syntax where
> the value before the colon was the name of an MDC key. I now changed the
> layout to the following:
>
> *log4j.appender.bundle_trace.appender.layout.ConversionPattern=%d{ISO8601}
> | bundle.name:%X{bundle.name} | %-5.5p | %-16.16t | %-32.32c{1} |
> %-32.32C %4L | %m%n*
>
> but the filter still didn't match. I then changed the string to match to
> something that occurs in a lot of messages (e g "Starting to poll") and
> noticed that exactly those lines were logged at TRACE level.
>
> Thanks for your help Guillaume. I know understand better how log4j filters
> work. I think I will probably create my own filter that tries to match a
> given MDC key to a certain value. This I think could be of value to others
> as well.
>
>
> /Bengt
>
> 2012/1/30 Guillaume Nodet <gn...@gmail.com>
>
>> The StringMatchFilter only apply the matching to the message, not the
>> full event, so the layout isn't taken into account.  And I don't think
>> any of the camel log message will contain "bundle.name:xxx".
>>
>> Why don't you attach a specific appender to org.apache.camel logger
>> instead ?  Else you'll have to define your own filter.  I guess
>> generic filters could be added to pax-logging if they're missing.
>>
>> On Mon, Jan 30, 2012 at 12:00, Bengt Rodehav <be...@rodehav.com> wrote:
>> > I also tried the following:
>> >
>> >
>> log4j.appender.bundle_trace.filter.a=org.apache.log4j.varia.StringMatchFilter
>> > log4j.appender.bundle_trace.filter.a.StringToMatch=bunde.name:
>> org.apache.camel.camel-core
>> > log4j.appender.bundle_trace.filter.a.AcceptOnMatch=false
>> >
>> > I didn't use a DenyAllFilter in this case. If the StringMatchFilter
>> worked,
>> > I would expect to get trace logfiles for all bundles
>> > EXCEPT org.apache.camel.camel-core.. But I get trace logfiles for all
>> > bundles including org.apache.camel.camel-core.
>> >
>> > I think this indicates that the problem is the StringMatchFilter and
>> not the
>> > DenyAllFilter...
>> >
>> > I have verified that the bundle name is written correctly. Could it be
>> some
>> > escape problems connected to config admin?
>> >
>> > /Bengt
>> >
>> >
>> >
>> >
>> > 2012/1/30 Bengt Rodehav <be...@rodehav.com>
>> >>
>> >> I tried these four combinations:
>> >>
>> >> # 1
>> >>
>> >>
>> log4j.appender.bundle_trace.filter.a=org.apache.log4j.varia.StringMatchFilter
>> >>
>> >> log4j.appender.bundle_trace.filter.a.StringToMatch=bunde.name:
>> org.apache.camel.camel-core
>> >> log4j.appender.bundle_trace.filter.a.AcceptOnMatch=true
>> >>
>> log4j.appender.bundle_trace.filter.b=org.apache.log4j.varia.DenyAllFilter
>> >>
>> >> # 2
>> >>
>> log4j.appender.bundle_trace.filter.b=org.apache.log4j.varia.DenyAllFilter
>> >>
>> >>
>> log4j.appender.bundle_trace.filter.a=org.apache.log4j.varia.StringMatchFilter
>> >>
>> >> log4j.appender.bundle_trace.filter.a.StringToMatch=bunde.name:
>> org.apache.camel.camel-core
>> >> log4j.appender.bundle_trace.filter.a.AcceptOnMatch=true
>> >>
>> >> # 3
>> >>
>> log4j.appender.bundle_trace.filter.a=org.apache.log4j.varia.DenyAllFilter
>> >>
>> >>
>> log4j.appender.bundle_trace.filter.b=org.apache.log4j.varia.StringMatchFilter
>> >>
>> >> log4j.appender.bundle_trace.filter.b.StringToMatch=bunde.name:
>> org.apache.camel.camel-core
>> >> log4j.appender.bundle_trace.filter.b.AcceptOnMatch=true
>> >>
>> >> # 4
>> >>
>> >>
>> log4j.appender.bundle_trace.filter.b=org.apache.log4j.varia.StringMatchFilter
>> >>
>> >> log4j.appender.bundle_trace.filter.b.StringToMatch=bunde.name:
>> org.apache.camel.camel-core
>> >> log4j.appender.bundle_trace.filter.b.AcceptOnMatch=true
>> >>
>> log4j.appender.bundle_trace.filter.a=org.apache.log4j.varia.DenyAllFilter
>> >>
>> >> This would check if ordering of the configurations or filter naming
>> would
>> >> make a difference. Unfortunately none of the above work.
>> >>
>> >> But as soon as I comment out the DenyAllFilter, trace logfiles appear
>> in
>> >> the trace folder. So, either the DenyAllFilter prevents the
>> >> StringMatchFilter from working or the StringMatchFilter never
>> "matches"...
>> >>
>> >> /Bengt
>> >>
>> >>
>> >>
>> >>
>> >>
>> >> 2012/1/30 Guillaume Nodet <gn...@gmail.com>
>> >>>
>> >>> Looking at the log4j code, it seems the filters are ordered using
>> >>> their ids, so in your case "accept" and "deny".
>> >>> So I think the order should be ok.  Can you try changing their name so
>> >>> that the order would be reversed ?
>> >>>
>> >>> On Mon, Jan 30, 2012 at 11:09, Bengt Rodehav <be...@rodehav.com>
>> wrote:
>> >>> > OK - I didn't know that.
>> >>> >
>> >>> > Do you think I should post a message on ops4j's mailing list about
>> >>> > this?
>> >>> >
>> >>> > The reason I tried the Karaf mailing list first is that I believe
>> this
>> >>> > whould be a pretty common (and useful) configuration. In my case, I
>> >>> > will
>> >>> > probably create logs per camel context and not per bundle but I
>> still
>> >>> > need
>> >>> > the possiblity to configure more detailed logging for a specific MDC
>> >>> > value.
>> >>> >
>> >>> > Have you tried something similar yourself?
>> >>> >
>> >>> > I actually posted a question on Stackoverflow about this as well:
>> >>> >
>> >>> >
>> >>> >
>> http://stackoverflow.com/questions/9049119/set-log-level-based-on-mdc-value-in-log4j
>> >>> >
>> >>> > No replies unfortunately. The filtering approach would be an
>> >>> > alternative
>> >>> > (although not as elegant way) to accomplish what I wanted.
>> >>> >
>> >>> > /Bengt
>> >>> >
>> >>> > 2012/1/30 Guillaume Nodet <gn...@gmail.com>
>> >>> >>
>> >>> >> No, the support has been added in log4j:
>> >>> >>   http://svn.apache.org/viewvc?view=revision&revision=821430
>> >>> >>
>> >>> >> On Mon, Jan 30, 2012 at 10:30, Bengt Rodehav <be...@rodehav.com>
>> >>> >> wrote:
>> >>> >> > Hello Guillaume,
>> >>> >> >
>> >>> >> > Doesn't the filter support in log4j require XML configuration
>> (not
>> >>> >> > properties file)? If so, then I assume that Pax-logging has added
>> >>> >> > the
>> >>> >> > possibility to use filters using a properties file configuration.
>> >>> >> >
>> >>> >> > /Bengt
>> >>> >> >
>> >>> >> >
>> >>> >> > 2012/1/30 Guillaume Nodet <gn...@gmail.com>
>> >>> >> >>
>> >>> >> >> Actually, the filters support is built into log4j, but if
>> there's
>> >>> >> >> really a problem we can always fix it in pax-logging until the
>> >>> >> >> patch
>> >>> >> >> is released in log4j.
>> >>> >> >>
>> >>> >> >> On Mon, Jan 30, 2012 at 10:21, Guillaume Nodet <
>> gnodet@gmail.com>
>> >>> >> >> wrote:
>> >>> >> >> > The filter support has been added in pax-logging.
>> >>> >> >> > Have a look at
>> >>> >> >> >
>> >>> >> >> >
>> >>> >> >> >
>> >>> >> >> >
>> https://github.com/ops4j/org.ops4j.pax.logging/blob/master/pax-logging-service/src/main/java/org/apache/log4j/PaxLoggingConfigurator.java
>> >>> >> >> >
>> >>> >> >> > You may very well be right that the order isn't kept, which
>> would
>> >>> >> >> > definitely be a bug.
>> >>> >> >> >
>> >>> >> >> > On Mon, Jan 30, 2012 at 10:17, Bengt Rodehav <
>> bengt@rodehav.com>
>> >>> >> >> > wrote:
>> >>> >> >> >> I have the following configuration in
>> >>> >> >> >> my org.ops4j.pax.logging.cfg:
>> >>> >> >> >>
>> >>> >> >> >> # Per bundle log at INFO level
>> >>> >> >> >>
>> log4j.appender.bundle=org.apache.log4j.sift.MDCSiftingAppender
>> >>> >> >> >> log4j.appender.bundle.key=bundle.name
>> >>> >> >> >> log4j.appender.bundle.default=karaf
>> >>> >> >> >>
>> >>> >> >> >>
>> log4j.appender.bundle.appender=org.apache.log4j.RollingFileAppender
>> >>> >> >> >> log4j.appender.bundle.appender.MaxFileSize=10MB
>> >>> >> >> >> log4j.appender.bundle.appender.MaxBackupIndex=2
>> >>> >> >> >>
>> >>> >> >> >>
>> log4j.appender.bundle.appender.layout=org.apache.log4j.PatternLayout
>> >>> >> >> >>
>> >>> >> >> >>
>> log4j.appender.bundle.appender.layout.ConversionPattern=%d{ISO8601}
>> >>> >> >> >> |
>> >>> >> >> >> %-5.5p
>> >>> >> >> >> | %-16.16t | %-32.32c{1} | %-32.32C %4L | %m%n
>> >>> >> >> >>
>> >>> >> >> >>
>> >>> >> >> >>
>> >>> >> >> >> log4j.appender.bundle.appender.file=${logdir}/bundles/$\\{
>> bundle.name\\}.log
>> >>> >> >> >> log4j.appender.bundle.appender.append=true
>> >>> >> >> >> log4j.appender.bundle.threshold=INFO
>> >>> >> >> >>
>> >>> >> >> >> # TRACE level for specific bundle - should normally be
>> disabled
>> >>> >> >> >>
>> >>> >> >> >>
>> log4j.appender.bundle_trace=org.apache.log4j.sift.MDCSiftingAppender
>> >>> >> >> >> log4j.appender.bundle_trace.key=bundle.name
>> >>> >> >> >> log4j.appender.bundle_trace.default=karaf
>> >>> >> >> >>
>> >>> >> >> >>
>> >>> >> >> >>
>> >>> >> >> >>
>> log4j.appender.bundle_trace.appender=org.apache.log4j.RollingFileAppender
>> >>> >> >> >> log4j.appender.bundle_trace.appender.MaxFileSize=20MB
>> >>> >> >> >> log4j.appender.bundle_trace.appender.MaxBackupIndex=1
>> >>> >> >> >>
>> >>> >> >> >>
>> >>> >> >> >>
>> >>> >> >> >>
>> log4j.appender.bundle_trace.appender.layout=org.apache.log4j.PatternLayout
>> >>> >> >> >>
>> >>> >> >> >>
>> >>> >> >> >>
>> >>> >> >> >>
>> log4j.appender.bundle_trace.appender.layout.ConversionPattern=%d{ISO8601} |
>> >>> >> >> >> %-5.5p | %-16.16t | %-32.32c{1} | %-32.32C %4L | %m%n
>> >>> >> >> >>
>> >>> >> >> >>
>> >>> >> >> >>
>> >>> >> >> >>
>> log4j.appender.bundle_trace.appender.file=${logdir}/bundles/trace/$\\{
>> bundle.name\\}.log
>> >>> >> >> >> log4j.appender.bundle_trace.appender.append=true
>> >>> >> >> >> log4j.appender.bundle_trace.threshold=TRACE
>> >>> >> >> >>
>> >>> >> >> >>
>> >>> >> >> >>
>> >>> >> >> >>
>> log4j.appender.bundle_trace.filter.accept=org.apache.log4j.varia.StringMatchFilter
>> >>> >> >> >>
>> >>> >> >> >>
>> >>> >> >> >>
>> >>> >> >> >>
>> log4j.appender.bundle_trace.filter.accept.StringToMatch=bunde.name:
>> org.apache.camel.camel-core
>> >>> >> >> >> log4j.appender.bundle_trace.filter.accept.AcceptOnMatch=false
>> >>> >> >> >>
>> >>> >> >> >>
>> >>> >> >> >>
>> >>> >> >> >>
>> log4j.appender.bundle_trace.filter.deny=org.apache.log4j.varia.DenyAllFilter
>> >>> >> >> >>
>> >>> >> >> >> The intention is to have bundle specific logs at INFO level
>> but
>> >>> >> >> >> have
>> >>> >> >> >> a
>> >>> >> >> >> separate TRACE log for a specific bundle. The latter is not
>> >>> >> >> >> enabled
>> >>> >> >> >> by
>> >>> >> >> >> default but only when debugging.
>> >>> >> >> >>
>> >>> >> >> >> The problem is that the DenyAllFilter seems to take
>> precedence
>> >>> >> >> >> over
>> >>> >> >> >> the
>> >>> >> >> >> StringMatchFilter. I believe that when listed in the order I
>> do,
>> >>> >> >> >> the
>> >>> >> >> >> bundle
>> >>> >> >> >> with the name "org.apache.camel.camel-core" should be logged
>> at
>> >>> >> >> >> TRACE
>> >>> >> >> >> level
>> >>> >> >> >> but no other bundles. Could it be that the ordering of
>> filters
>> >>> >> >> >> are
>> >>> >> >> >> not
>> >>> >> >> >> preserved? I think that native log4j only supports filters
>> when
>> >>> >> >> >> using
>> >>> >> >> >> XML
>> >>> >> >> >> configuration and I assume that the Karaf filtering support
>> has
>> >>> >> >> >> been
>> >>> >> >> >> added
>> >>> >> >> >> on top of log4j (or is it in Pax-logging)? Has the ordering
>> of
>> >>> >> >> >> filters
>> >>> >> >> >> been
>> >>> >> >> >> taken into account?
>> >>> >> >> >>
>> >>> >> >> >> I've been testing this on Karaf 2.2.0 with Pax logging 1.6.0.
>> >>> >> >> >>
>> >>> >> >> >> /Bengt
>> >>> >> >> >
>> >>> >> >> >
>> >>> >> >> >
>> >>> >> >> > --
>> >>> >> >> > ------------------------
>> >>> >> >> > Guillaume Nodet
>> >>> >> >> > ------------------------
>> >>> >> >> > Blog: http://gnodet.blogspot.com/
>> >>> >> >> > ------------------------
>> >>> >> >> > FuseSource, Integration everywhere
>> >>> >> >> > http://fusesource.com
>> >>> >> >>
>> >>> >> >>
>> >>> >> >>
>> >>> >> >> --
>> >>> >> >> ------------------------
>> >>> >> >> Guillaume Nodet
>> >>> >> >> ------------------------
>> >>> >> >> Blog: http://gnodet.blogspot.com/
>> >>> >> >> ------------------------
>> >>> >> >> FuseSource, Integration everywhere
>> >>> >> >> http://fusesource.com
>> >>> >> >
>> >>> >> >
>> >>> >>
>> >>> >>
>> >>> >>
>> >>> >> --
>> >>> >> ------------------------
>> >>> >> Guillaume Nodet
>> >>> >> ------------------------
>> >>> >> Blog: http://gnodet.blogspot.com/
>> >>> >> ------------------------
>> >>> >> FuseSource, Integration everywhere
>> >>> >> http://fusesource.com
>> >>> >
>> >>> >
>> >>>
>> >>>
>> >>>
>> >>> --
>> >>> ------------------------
>> >>> Guillaume Nodet
>> >>> ------------------------
>> >>> Blog: http://gnodet.blogspot.com/
>> >>> ------------------------
>> >>> FuseSource, Integration everywhere
>> >>> http://fusesource.com
>> >>
>> >>
>> >
>>
>>
>>
>> --
>> ------------------------
>> Guillaume Nodet
>> ------------------------
>> Blog: http://gnodet.blogspot.com/
>> ------------------------
>> FuseSource, Integration everywhere
>> http://fusesource.com
>>
>
>