Logging on j2ee apps, more of a model advice

theTinker

I've been a little annoyed by the logging (using Log4J) in alot of applications that I currently work on. So im trying to find a way to fix it. The rest of this thread is my idea and questions.

I'm a naive grad btw

My main gripe with it is: all logging is usually wrote to a single log file. The type of applications usually are J2EE web apps(internal + external). The apps are the same as most, a fair few users, they log on, do stuff which requires an audit trail, then finish or in some cases: cause an error, exception, uncover a bug...etc.

I've decided to try come up with a better model to use often. Firstly i don't like that all audit logging is done linearly ordered by time, regardless of the user. So we end up with

Sharon did this
Sharon did that
Rob logged on
Jake entered an invalid password
Sharon did something else.


We've a few hundred users on different systems so this gets messy real fast.
One idea was to log to files dynamically named(by userId), this could be done programmatically in java by setting the loggers file appender to the "USERID.LOG". I think so anyways. What do yous think of this? would this become far too difficult to maintain with all the files being generated? Would log4j bomb on something like this with a couple hundred users?
I suppose an alternative would be to keep logging into the one file but then make it a consistent pattern and build a filter applications that would extract details from "Sharon" only and display them....hmm....that might be better.

Secondly, using for instance, Struts. In the action classes we have access to the "user" object in the HttpSession etc, It makes logging an 'event by user' easy. At the lower DAO layers etc, The user id isn't passed about. So in order to log an event coupled with a user id, would it be good practice to have a static LoggerFactory with a static 'logger' variable that i can set a "userid.log" output path to and simply call this when ever i need to get a hold of the logger? Its not application wide right? its would just a singleton object for that particular users request-response combo?.....hmmm...i need to define that more in my head i think. Im getting a little confused about static scope in a webapp which shares many users. Is it the same as an application scope singleton? I want a static variable accessible by any class but the variable is statically unqiue to only a single users scope. Any ideas?

Thirdly, In the event of a serious exception, I want to record the system state in a much more accurate manner than simply looking for a few key variables like userId + a few params. I would like a dump out of objects within the scope of the exception.(serious exceptions only would implement this part).
My idea for this would be to generate an Exception Code, dump the state of the objects into a file named by the exception code and then log the exception code coupled with the userID in a "theseExceptionsHappened.log".
Obviously i would also log a note in the usual audit logs too with the exception code.
I would like to log the objects state in XML so i can rebuild them into mock objects in a few seconds using a parse like XStream. This would be very helpful in some situations and would allow me to recreate the problem easily and exactly. It would also allow testing of the solution in a better way. Can anyone see a problem with this approach? Would the performance hit be negliable in your opinion? Any other opinions or advice on this? Suggestions for implementations? Holes in my thinking?

cousin_borat

Its an interesting idea, I am having similar problems using log4j in a middleware environment as well.

theserverside.com or http://saloon.javaranch.com/cgi-bin/ubb/ultimatebb.cgi
are probably better bets to post your question. I doubt you'll get any replies here, most questions are very specific "how do I get my loop to work" type stuff

aidan_walsh

Rather than rewriting the entire logging system, would you not be better off writing an app that loads the log file and allows you to manipulate the display as you prefer?

theTinker

I hope this doesn't come across as snotty but do you mean like what i wrote at the end of my first question/solution?
"I suppose an alternative would be to keep logging into the one file but then make it a consistent pattern and build a filter applications that would extract details from "Sharon" only and display them....hmm....that might be better."

I was thinking more about it today and it would make alot more sense to do it that way. It would also mean alot less implementation work through out the application which would keep it alot cleaner.

Im still...stuck on how i would get a userID to be coupled with an event right through out the system. I am not going to pass a User object/String through the whole applications functions. Thats just ridiculous. Any ideas?

I experimented with the State dumping using the XStream XML parse last night. Caused a mock exception based on some values. Logged them out under an "Unqiue Exception code" filename and dumped the state. I was quickly able to load them back in for testing of a solution and for problem recreation. I'm definitely gonna keep that bit.

Afuera

theTinker wrote:

Im still...stuck on how i would get a userID to be coupled with an event right through out the system. I am not going to pass a User object/String through the whole applications functions. Thats just ridiculous. Any ideas?

What parameters are of importance to you? Would it be enough to just supply the userID so that you have a unique log for each? If so then I think it might be ok to just supply that each time to a static function.

theTinker wrote:

I experimented with the State dumping using the XStream XML parse last night. Caused a mock exception based on some values. Logged them out under an "Unqiue Exception code" filename and dumped the state. I was quickly able to load them back in for testing of a solution and for problem recreation. I'm definitely gonna keep that bit.

This sounds interesting alright and could be a very useful tool for debugging. Best of luck with it and let us know how you get on.

Dopey

You can use java.lang.ThreadLocal for this and a static class.

When a user performs an action you presumably have the userId. Create a class called UserContext with a static ThreadLocal class variable and static set and get methods that take and return a userId.

In your DAO class, for example, call the UserContext.getUser() method. It will pull the userId from the ThreadLocal class and you can use it for logging. ThreadLocal is used by application servers like WebLogic to internally store user credentials. It's perfect for this.

Creating loads of log4j output files is unnecessary and slow. Every time a new user logs in you will need to get a file handle to possibly create a new file. There is a performance impact.

Use grep or write a Java app to parse the log files for the userId and output to a userId.log file sorted by time.

Khannie

theTinker wrote:

I suppose an alternative would be to keep logging into the one file but then make it a consistent pattern and build a filter applications that would extract details from "Sharon" only and display them....hmm....that might be better.

Once the string is consistent, this is really what you're looking for (grep or less would work for example). I haven't used log4j directly, but I have used log4cxx (which is based on log4j). In our case, each thread was given a threadid in the output. To follow (for example) Sharons actions, you would grep for her threadid throughout the log file.

You could create per-user log files also (temporarily duplicating what's in the large log file), perhaps storing them on ramdisk (to avoid disk I/O) or thread the writing (to avoid blocking on I/O), and delete them on logout if the session doesn't throw up any problems.

You lost me on the 2nd part, and I think you have the 3rd part sorted.

theTinker

Dopey wrote:

You can use java.lang.ThreadLocal for this and a static class.

When a user performs an action you presumably have the userId. Create a class called UserContext with a static ThreadLocal class variable and static set and get methods that take and return a userId.

In your DAO class, for example, call the UserContext.getUser() method. It will pull the userId from the ThreadLocal class and you can use it for logging. ThreadLocal is used by application servers like WebLogic to internally store user credentials. It's perfect for this.

Creating loads of log4j output files is unnecessary and slow. Every time a new user logs in you will need to get a file handle to possibly create a new file. There is a performance impact.

Use grep or write a Java app to parse the log files for the userId and output to a userId.log file sorted by time.

you genius, which effectively makes me a genius too. why?
I was talking to a Peer today and he mentioned the ThreadLocal class. I was completely unaware of it. Ive been reading up on it for the last 20 mins and it looks perfect.


I logged on to report my status

I subclassed Log4j's pattern and layout classes so I could implement my own %u pattern character to print out the username. I'm trying to come up with a template we can use on other apps and theres NO WAY i can count on each developer to keep retrieving the UserId and log it correctly. Far too much writing+strings+bloating+errors would happen. Right at the conversion process of converting the LoggingEvent pattern into messages(%u), I insert the UserId automatically. I'm hoping to create a static class that i can just call at my pattern conversion time. It will be up to the application developer to add the UserId to the ThreadLocal storage at the start of each UI Server Process, eg: struts action... I THINK thats how it will work. I'll keep reporting.

Any advice welcome.

Thanks so far.

theTinker

I was able to work out that ThreadLocal thingy.
Im putting it up for others reference plus if somebody could verify that the static call returns a instance value per thread.
The best names i found for it on the web is a "Per Thread singleton" or a "Thread scoped object".

I dont have a web application server on this machine since im at home at the moment so i just made a main method with two running threads. Each thread just sets the UserId into the static class, then every second just calls it statically. If the value worked like a normal static variable then it would be over written by the second setter call and just all be the same. Its different so it must retain its state.....Thats my thinking anyway. If its flawed, please point it out
Output was:
User One
User Two
User One
User Two
User One
User Two

The output was what I expected for a successful run.

3 classes were used here:

• The ThreadLocal class which stores the value and allows static access to it from anywhere in the same thread.
• A Main to execute the program(just to kick it off)
• A Runner class simulating two threads like users on a WebApp.

---

Start Main Class

---

public class Main {
//starts 2 threads
public static void main(String[] args) {
Runner one = new Runner("User One");
one.start();
Runner two = new Runner("User Two");
two.start();
}
}

---

End Main Class

---

---

Start Runner Class

---

public class Runner extends Thread {

private String identToUse = null;

public Runner(String identToUse){
this.identToUse = identToUse;
}

public void run(){
/*simulates setting the UserId at the start of a struts action, server processing event*/
IdentHolder.setIdent(identToUse);

while(true){
try {
//makes static call retrieving the per thread singleton.
System.out.println(IdentHolder.getIdent());
Thread.currentThread().sleep(1500);
} catch (InterruptedException e) {
e.printStackTrace();
}
} //end while

}
}

---

End Runner Class

---

---

Start ThreadLocal Class

---

public class IdentHolder {

private static IdentHolder holder = new IdentHolder();
private ThreadLocal threadLocal = new ThreadLocal();

public Object getCurrentIdent() {
return threadLocal.get();
}

public void setCurrentIdent(Object ident) {
threadLocal.set(ident);
}

public static Object getIdent() {
return holder.getCurrentIdent();
}

public static void setIdent(Object ident) {
holder.setCurrentIdent(ident);
}
}

---

End ThreadLocal Class

---

theTinker

Khannie wrote:

You lost me on the 2nd part

My 2nd part was written a bit poorly. The point i was making was:
When a user executes a request from a server(in a standard web app like struts). The first application class like Struts action executes. Its Easy to record log messages with the user Id here since we can usually just grab it from a HttpSession object. The struts action for example then calls other methods at 'lower' levels, such as database access, factories, utilities, etc. Most of the applications i've been looking at also log at lower levels(methods/operations not in the struts action) but the UserId is not available at the lower levels so the event is usually just a "this happened" with no way to check who triggered it. My above solution should solve this. Im surprised its not implemented already in the applications.

I can understand that it wont be extremely useful but i think there will be some use from it like more accurate auditing in some situations. Since its now easy to implement though, it could come in handy for critical operations.
It would also be easy to quickly build a filter set to show log events from user "A". So it would be like a completed storyboard of the operations run by this user, etc. This is also the solution to part number 1

theTinker

I was just tweaking the results a little and it turns out I can reduce the class with the same functionality.

Theres a nice article on ThreadLocal at
http://www-128.ibm.com/developerworks/java/library/j-threads3.html

Though, the part on the DebugLogger makes a static reference to a non-static method so the code is slightly wrong I think.

Heres the new tweaked version which gives the same results. The way is works is the internal implementation of ThreadLocal, gets the Thread.currentThread() and writes what ever value you are setting in a HashMap with the Thread.currentThread() as the key identifying it. Nice little tool. Awesome potential on the logging side.

---

public class IdentHolder {

private static ThreadLocal threadLocal = new ThreadLocal();

public static Object getCurrentIdent() {
return threadLocal.get();
}

public static void setCurrentIdent(Object ident) {
threadLocal.set(ident);
}
}

---

I plan to suggest an idea i read about. Log all Audit events like normal using the UserID retrieved from the Thread Local. Log all Debug info to a list in the ThreadLocal. If there is any problems throughout the thread execution then log all the debug info to a file. Otherwise dont bother and let the garbage collector wipe the thread and accompanying debug info.(might be a nice idea to Clear the list for safety)

Edit: Nice article on logging(java) from IBM, speaks of logging userId with event, and storing state of objects with XML(Xstream specifically!)

theTinker

Done some more work.

Some really good news and some fustrating bad news....

First the Good
For the purpose of logging the username with the event. Using a custom log4j PatternParser and a ThreadLocal's per thread storage is the perfect way to do it. Works like a charm and does it all automatically so only a single call at the start of the server request/struts action needs to be done.

Secondly the bad:...
It was SO good a way of doing it that...
yes Log4J already implemented all of this since jdk 1.2-1.3 timeframe.
Its called MCD.
Use a MCD.put("ID", value) at the start of a server request.
add: %X{ID} to the conversion pattern in log4j.properties. and walla! its done... it will log the value for the key ID. I have yet to check out the internal implementation but its quite likely using the ThreadLocal or else its re-inventing a slower wheel.

So as far as the username problem with events. Its a done and dusted problem. I can't believe none of peers where able to inform me about this in work. Quite the obvious for someone with experience i would think. Its such a powerful feature. Im quite glad to learn about the ThreadLocal class though.
Using it to save up debug information and only it if a problem occurs will certainly save log files LOTS of space and save overall performance on average.

IBM experimented with XStream technology parsing POJO's for state recording. It seemed successful once it was only used in situations where its actually needed such as error or exceptions. Anything else resulted in too verbose a log output.

Thanks for all your help!