Hello,
I tried the DynamicThresholdFilter suggestion, and it worked nice, so did the
sifting appender. I didn't tested the ThresholdFilter, as in the end it seems
it was not a good idea to forbid the user events to go to the STANDARD file...
it is a "master log file" after all, better let it be complete. Thanks again
for all the suggestions, Ralph.
However, the DynamicThresholdFilter generated more logging than desired for
many less important loggers. As a refinement of the idea, I created a custom
TurboFilter with similar capabilities, but specific per logger too. I'm posting
below my new XML config and filters, someone else may use it, plus I'd like
some suggestions on ugly parts of the code ;-) (see FIXME comments below).
Some of my new config XML:
<configuration debug="true">
<turboFilter class="com.sample.project.CustomTurboFilter">
<userCustomization>
<user>ID_USER_1</user> <loggerLevel>
<logger>com.sample.project</logger>
<level>DEBUG</level> </loggerLevel>
<loggerLevel>
<logger>com.sample.legacy</logger>
<level>INFO</level> </loggerLevel>
</userCustomization> <userCustomization>
<user>ID_USER_2</user> <loggerLevel>
<logger>com.sample.project</logger>
<level>TRACE</level> </loggerLevel>
... </userCustomization>
</turboFilter>
<appender name="FILTERED"
class="ch.qos.logback.classic.sift.SiftingAppender">
<discriminator class="ch.qos.logback.classic.sift.MDCBasedDiscriminator">
<key>userId</key>
<defaultValue>unknown</defaultValue> </discriminator>
<filter class="com.sample.project.CustomFilter"/>
<sift> ... </sift> </appender>
<logger name="com.sample.project" level="WARN">
<appender-ref ref="FILTERED" /> </logger> <root
level="WARN"> <appender-ref ref="STANDARD" />
</root>
</configuration>
The CustomTurboFilter:
public class CustomTurboFilter extends TurboFilter {
private Map<String,Map<String,Level>> userCustomizationsMap = new
HashMap<String, Map<String,Level>>(); private Set<String>
customizedUsersSet; public FilterReply decide(Marker marker,
Logger logger, Level level, String format, Object[] params, Throwable
throwable) { if (!isStarted())
return FilterReply.NEUTRAL; String user =
MDC.get("userId"); if (user == null)
return FilterReply.NEUTRAL;
Map<String, Level> map =
userCustomizationsMap.get(user); if (map == null)
return FilterReply.NEUTRAL; //undefined user
//test each logger-level for this user, find the closest
match to 'logger' String loggerName = logger.getName();
Level specificLoggerLevel = null; int
specificLoggerNameLength = -1; for (Entry<String, Level> e
: map.entrySet()) { String name = e.getKey();
//FIXME This is awful code, I know, but I found no other
way to check logger hierarchy (and LoggerComparator is not fit for this)
//FIXME guess it could be a bit faster using only
'startsWith', 'length' and 'charAt', but still String manipulation
if (loggerName.equals(name)) {
specificLoggerLevel = e.getValue(); //exact logger match
break; }
//FIXME Here I attempt to find the most specific logger definition for the
current logger (awful too) int length =
name.length(); if (loggerName.startsWith(name+".")
&& length > specificLoggerNameLength) {
//the logger in this definition is a parent of 'logger', and longer name than
the last one specificLoggerNameLength =
length; specificLoggerLevel =
e.getValue(); } }
if (specificLoggerLevel != null &&
level.isGreaterOrEqual(specificLoggerLevel)) {
return FilterReply.ACCEPT; //match found, force accept } else
{ return FilterReply.NEUTRAL; //no matching
logger found, ignore } }
public void addUserCustomization(UserLoggersMapping userLoggersMapping) {
String user = userLoggersMapping.getUser();
user = (user == null ? "" : user.trim()); if
(!user.isEmpty() && !userCustomizationsMap.containsKey(user)) {
Map<String,Level> loggerLevelMap = new HashMap<String, Level>();
for (LoggerLevelPair llp :
userLoggersMapping.getLoggerLevelList()) {
String logger = llp.getLogger(); logger
= (logger == null ? "" : logger.trim()); if
(!logger.isEmpty() && !loggerLevelMap.containsKey(logger) && llp.getLevel() !=
null) {
addInfo("Logger["+logger+"] level customized to "+llp.getLevel()+" for user
"+user); loggerLevelMap.put(logger,
llp.getLevel()); }
} if (!loggerLevelMap.isEmpty()) {
userCustomizationsMap.put(user, loggerLevelMap);
} } }
public Set<String> getCustomizedUsersSet() {
return customizedUsersSet; } public void
start() { customizedUsersSet =
Collections.unmodifiableSet(userCustomizationsMap.keySet()); //Will be used by
CustomFilter super.start(); }
//Just JavaBeans, also shortening the code :-P public
static class UserLoggersMapping { private String user;
private List<LoggerLevelPair> loggerLevelList = new
ArrayList<LoggerLevelPair>(); private String getUser()
{return user;} public void setUser(String user) {this.user =
user;} private List<LoggerLevelPair> getLoggerLevelList()
{return loggerLevelList;} public void
addLoggerLevel(LoggerLevelPair levelLoggerPair)
{loggerLevelList.add(levelLoggerPair);} }
public static class LoggerLevelPair { private Level level;
private String logger; private Level
getLevel() {return level;} public void setLevel(Level
level) {this.level = level;} private String getLogger() {return
logger;} public void setLogger(String logger) {this.logger
= logger;} } }
The CustomFilter. It is optional, used to deny sifted logging to users not
specified by the CustomTurboFilter:
public class CustomFilter extends Filter<ILoggingEvent> {
private Set<String> customizedUsersSet;
public FilterReply decide(ILoggingEvent event) {
//deny anything but a user filtered by CustomTurboFilter
if (!isStarted() || customizedUsersSet == null)
return FilterReply.DENY;
String user = MDC.get("userId");
if (user == null) return FilterReply.DENY;
return customizedUsersSet.contains(user) ?
FilterReply.NEUTRAL : FilterReply.DENY; }
public void start() { //FIXME is this safe?
Joran's sequential processing seems to make it so
Iterator<TurboFilter> iterator = ((LoggerContext)
getContext()).getTurboFilterList().iterator(); while
(iterator.hasNext()) { TurboFilter tf =
iterator.next(); if (tf instanceof
CustomTurboFilter) { customizedUsersSet =
((CustomTurboFilter) tf).getCustomizedUsersSet();
addInfo("Allowed users: " + customizedUsersSet);
break; } }
if (customizedUsersSet == null) addWarn("No
matching TurboFilter found"); super.start(); }
}
So, can I improve the code somehow, or is there another approach to evaluate?
All contributions are most welcome.
Thanks again!
From: [email protected]
Date: Thu, 15 Dec 2011 07:32:10 -0800
To: [email protected]
Subject: Re: [logback-user] User-filtered logging - can be done?
I took a look at Logger.java. You are correct that the effective level is
stored so there is no performance overhead. That still wouldn't change my
recommendation though.
As for the SiftingAppender, yes you would get a file for each user. It would
contain Warn events for those who pass the defaultThreshold and debug events,
etc. for those explicitly configured. With the RollingFileAppender you will
still get all those same events, just in a single file.
Ralph
On Dec 15, 2011, at 5:32 AM, Y M wrote:
Ralph,
Many thanks for your reply.
> Your configuration is not a great way to do it. Every event that passes the
> log level will get passed to the appender for filtering by user. This is more
> expensive than having the filter be a turbo filter.
> The way I would handle this is to use the DynamicThresholdFilter.
Yes, this turbo filter is precisely what I need to do the user level filtering.
It was so briefly mentioned in the manual that I barely took notice of it, and
never inspected its capabilities. It would further allow user filtered events
in loggers other than 'com.sample.project', but not a problem, maybe even
better.
>If you want each user to log to a separate file then use the SiftingAppender
>to route the log events to a log file for that user regardless of the logger.
Not a requirement right now, but I may try it once I get everything else right.
But I a sifting would make all events from 'com.sample.project' log to separate
user files (i.e. I'd get a file for user 999999 containing its WARN events,
despite not targetting it for finer logging through the turbo filter), am I
right? That's something I'd like to avoid, as the application currently handles
a few hundred users at any time, and a dozen new user specific log files every
day would not be desirable.
> The configuration below accepts the event if it is from a specific user
> regardless of its level. All others flow through unimpeded. Unfortunately, if
> you don't want debug events for the user logged to LEGACY or STDOUT then you
> will need to add a ThresholdFilter to those two appenders. However, this
> isn't as bad since they will only be for that single user.
If I understood correctly, to mimic this appending behavior I want: the
ThresholdFilter on STANDARD (example) will need to "double filter" on WARN,
removing the DEBUG+ events allowed by the turbo filter, is that it? I may think
this is a bit inefficient, but more out-of-the-box than other solutions, like
creating a custom logger (if that could do it somehow).
> Notice I specified the log level on all the loggers. IMO this is better in
> practice because a) the hierarchy doesn't have to be searched all the way to
> the parent on each event so it will perform better and b) it is less
> confusing to people looking a the configuration, especially when you specify
> additivity.
a) I'm afraid this is not correct, the 'Performance' section in Architecture
Chapter of the manual says every logger always knows its effective level and
it is notified when it changes; if some efficiency would be achieved, it would
be during start up or during level changes while running (or so it seems :-)b)
you may be right on this... I usually go for a 'less code, more convention'
rule, it also makes level changes simpler (also because I use conditional
processing for test environment, and changing only the ROOT level is simpler)
Thanks for the great answer, I'll definitely try it and post a follow-up.If
anybody knows a different approach, I'd be glad to try it.
Thanks again!
> From: [email protected]
> Date: Wed, 14 Dec 2011 23:52:29 -0800
> To: [email protected]
> Subject: Re: [logback-user] User-filtered logging - can be done?
>
> Your configuration is not a great way to do it. Every event that passes the
> log level will get passed to the appender for filtering by user. This is more
> expensive than having the filter be a turbo filter.
>
> The way I would handle this is to use the DynamicThresholdFilter. If you want
> each user to log to a separate file then use the SiftingAppender to route the
> log events to a log file for that user regardless of the logger.
>
> The configuration below accepts the event if it is from a specific user
> regardless of its level. All others flow through unimpeded. Unfortunately,
> if you don't want debug events for the user logged to LEGACY or STDOUT then
> you will need to add a ThresholdFilter to those two appenders. However, this
> isn't as bad since they will only be for that single user.
>
> Notice I specified the log level on all the loggers. IMO this is better in
> practice because a) the hierarchy doesn't have to be searched all the way to
> the parent on each event so it will perform better and b) it is less
> confusing to people looking a the configuration, especially when you specify
> additivity.
>
> <configuration>
> <turboFilter class="ch.qos.logback.classic.turbo.DynamicThresholdFilter">
> <Key>userId</Key>
> <DefaultThreshold>WARN</DefaultThreshold>
> <onLower>NEUTRAL</onLower>
> <onHigherOrEqual>ACCEPT</onHigherOrEqual>
> <MDCValueLevelPair>
> <value>123456</value>
> <level>DEBUG</level>
> </MDCValueLevelPair>
> </turboFilter>
>
> <appender name="FILTERED"
> class="ch.qos.logback.core.rolling.RollingFileAppender">
> ...
> </appender>
>
> <appender name="STDOUT"
> class="ch.qos.logback.core.ConsoleAppender">
> <layout class="ch.qos.logback.classic.PatternLayout">
> <Pattern>TEST %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} -
> %msg%n</Pattern>
> </layout>
> </appender>
>
> <logger name="com.sample.legacy" additivity="false" level="warn">
> <appender-ref ref="LEGACY"/>
> </logger>
>
> <logger name="com.sample.project" level="warn"> <!-- Add additivity="false"
> if you don't want these also logged to STDOUT -->
> <appender-ref ref="FILTERED"./>
> </logger>
>
> <root level="warn" >
> <appender-ref ref="STDOUT" />
> </root>
> </configuration>
>
> Ralph
>
> On Dec 14, 2011, at 3:50 PM, Chris Pratt wrote:
>
> > You might look at using the User Name as a Marker. Then you could set up a
> > filter that will filter on that User's Marker.
> > (*Chris*)
> >
> > On Wed, Dec 14, 2011 at 3:27 PM, Y M <[email protected]> wrote:
> > Hello,
> >
> > I'm trying to obtain a certain logging configuration, but so far I'm
> > unsuccessful. I've read through the Logback manual, but I don't know if I
> > can do what I want.
> >
> > It is a web application, and my objective is to enable a finer logging
> > level for specific users, getting written to a specific log file, allowing
> > better debugging directly in production environment. When needed, someone
> > will set a tuned XML config using JMX to enable logging for the duration of
> > the tests/data gathering (JMX is working fine). This is the relevant part
> > of my logback.xml file:
> >
> > <configuration debug="true">
> >
> > ...
> >
> > <appender name="FILTERED"
> > class="ch.qos.logback.core.rolling.RollingFileAppender">
> > <filter class="com.sample.project.UserFilter">
> > <!--
> > //filter code
> > if (level != null &&
> > !event.getLevel().isGreaterOrEqual(level)) {
> > return FilterReply.DENY;
> > }
> > if (user.equals(MDC.get("userId"))) {
> > return FilterReply.ACCEPT;
> > } else {
> > return FilterReply.DENY;
> > }
> >
> > -->
> > <level>DEBUG</level>
> > <user>123456</user>
> > </filter>
> >
> > ...
> > </appender>
> >
> > <logger name="com.sample.project">
> > <appender-ref ref="FILTERED" />
> > </logger>
> > <logger name="com.sample.legacy" additivity="false">
> > <appender-ref ref="LEGACY" />
> > </logger>
> > <root level="WARN">
> > <appender-ref ref="STANDARD" />
> > </root>
> >
> > </configuration>
> >
> > With this config, I intend to have:
> > - WARN+ level at root;
> > - events from legacy project tree only on 'LEGACY' (working fine);
> > - 'FILTERED' logging only DEBUG+ events from user '123456' under
> > 'com.sample.project', while its level ramains at WARN (not OK).
> >
> > Sample:
> > getLogger("com.sample.abc").warn("..."); //logged to STANDARD
> > getLogger("com.sample.abc").debug("..."); //not logged
> > getLogger("com.sample.legacy").warn("..."); //logged to LEGACY
> > getLogger("com.sample.project").warn("..."); //logged to STANDARD; also
> > logged to FILTERED if user is 123456
> > getLogger("com.sample.project").debug("..."); //logged to FILTERED if user
> > is 123456
> >
> > As I tested, a 'logger.debug()' from the desired user does not get logged,
> > the filter is not even called, and I suspect that the effective WARN level
> > denies the event before reaching my filter (I hoped for the other way
> > around). If I set DEBUG on 'com.sample.project', 'FILTERED' will get the
> > correct logging, but 'STANDARD' will be flooded with DEBUG+ logging from
> > 'com.sample.project'. And disabling additivity on it removes all logging
> > belonging to this hierarchy from 'STANDARD'.
> >
> > So, I see Logback is working properly, my desired logging seems to be
> > against the standard architecture. But is there a way to archive the
> > described effect?
> > I was thinking of a TurboFilter, allowing lower level events from selected
> > users (not tested yet), but I'm not sure the effective level would kick in
> > first, also it wouldn't do the desired logging separation between
> > 'STANDARD' and 'FILTERED' anyway. As another approach, maybe this would
> > require a custom Logger class, handling specific appenders in a special
> > way. Unfortunately, I have no idea if I can plug in custom Loggers, and
> > also not sure how to code it (Logger class source is quite complex in a
> > quick look).
> >
> > Sorry if it wasn't clear, I'm not sure how to present the situation. I can
> > provide further details, if needed.
> > Any help is welcome. If someone could show me which way to follow, maybe
> > classes or methods to extend, I'd be grateful.
> >
> > Many thanks!
> >
> > _______________________________________________
> > Logback-user mailing list
> > [email protected]
> > http://mailman.qos.ch/mailman/listinfo/logback-user
> >
> > _______________________________________________
> > Logback-user mailing list
> > [email protected]
> > http://mailman.qos.ch/mailman/listinfo/logback-user
>
> _______________________________________________
> Logback-user mailing list
> [email protected]
> http://mailman.qos.ch/mailman/listinfo/logback-user
_______________________________________________
Logback-user mailing list
[email protected]
http://mailman.qos.ch/mailman/listinfo/logback-user
_______________________________________________
Logback-user mailing list
[email protected]
http://mailman.qos.ch/mailman/listinfo/logback-user
_______________________________________________
Logback-user mailing list
[email protected]
http://mailman.qos.ch/mailman/listinfo/logback-user
