[logback-user] User-filtered logging - can be done?
Y M
ym119162 at hotmail.com
Tue Dec 20 17:08:30 CET 2011
I'm not sure if there is any real problem with line separators when I paste the code, but the archive shows my message totally screwed up, yet the email shows it correctly.Just to be sure, I posted the code to git, if anybody is having problems: https://gist.github.com/1502077
Sorry for the trouble!
From: ym119162 at hotmail.com
To: logback-user at qos.ch
Date: Tue, 20 Dec 2011 10:56:50 -0500
Subject: Re: [logback-user] User-filtered logging - can be done?
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: rgoers at apache.org
Date: Thu, 15 Dec 2011 07:32:10 -0800
To: logback-user at qos.ch
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: rgoers at apache.org
> Date: Wed, 14 Dec 2011 23:52:29 -0800
> To: logback-user at qos.ch
> 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 <ym119162 at hotmail.com> 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
> > Logback-user at qos.ch
> > http://mailman.qos.ch/mailman/listinfo/logback-user
> >
> > _______________________________________________
> > Logback-user mailing list
> > Logback-user at qos.ch
> > http://mailman.qos.ch/mailman/listinfo/logback-user
>
> _______________________________________________
> Logback-user mailing list
> Logback-user at qos.ch
> http://mailman.qos.ch/mailman/listinfo/logback-user
_______________________________________________
Logback-user mailing list
Logback-user at qos.ch
http://mailman.qos.ch/mailman/listinfo/logback-user
_______________________________________________
Logback-user mailing list
Logback-user at qos.ch
http://mailman.qos.ch/mailman/listinfo/logback-user
_______________________________________________
Logback-user mailing list
Logback-user at qos.ch
http://mailman.qos.ch/mailman/listinfo/logback-user
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.qos.ch/pipermail/logback-user/attachments/20111220/bc815380/attachment-0001.html>
More information about the Logback-user
mailing list