We recently replaced our in-house logging for something more “standard”; log4j-based based logger. The original code developed by out former employee was a mixture of spaghetti code and huge amount of non-threadsafe WTFs….
Following text comes with limited warranty – I’m not saying that what we did was the best solution to problem but it was the simplest one. At least we thought so.
We recently replaced our in-house logging for something more “standard”; log4j-based based logger. The original code developed by out former employee was a mixture of spaghetti code and huge amount of non-threadsafe WTFs. We spent some time fixing it but finally we’ve decided to replace it. In order to incorporate our additional features that had been part of the original logger, we extended java.util.logging.Logger. So far, so good; but then the real hell started. There comes the first mistake one should learn from – never ever replace anything that works with something that hadn’t been even tested properly.
After a while with new logger we noticed our server application started to die with OutOfMemoryException. As there was a lot of changes made everywhere no one really suspected logger. But nothing could be further from the truth; wrong usage of ByteArrayOutputStream which was never reset() caused the trouble, we found that after couple of hours of profiling as no one would suspect “runtime” classes to eat the memory.
Having fixed something so obvious we thought we were done. Well, not really. Server did not crash in two days, it went down after a week. Same exception, same source – new logger.
In order to explain the situation I have to start with out new features. We wanted to have similar log files separated by given parameter, all our topics are members of huge enum, some of the values can have an annotation specifying destination filename and default parameter. If such parameter is present in log record, it’s written in file based on given data; this helps us to sort data according to their source, even if log entries are created by the same code; quick example will explain it faster – imagine application reading data from email accounts – such an application would log with our logger to N+1 files named:
application.log
application_HOTMAIL.log
application_GMAIL.log
...
I guess you got the idea. In order to do that we needed a place where those parameters are stored and instances of java.util.logging.Logger class seemed as a logical place. We extended this class and our implementation added support for those additional data.
Simple, but… there comes the catch. Loggers live in hierarchical structure, each logger has a parent. Whenever new logger is created it’s assigned to a parent (parent could be root logger, of course). Each logger keeps its children in a java.util.List, see following excerpt from Sun’s Logger.java:
private Logger parent; // our nearest parent.
private ArrayList kids; // WeakReferences to loggers that have us as parent
public void setParent(Logger parent) {
if (parent == null) {
throw new NullPointerException();
}
(...)
doSetParent(parent);
}
private void doSetParent(Logger newParent) {
synchronized (treeLock) {
// Remove ourself from any previous parent.
(...)
// Set our new parent.
parent = newParent;
if (parent.kids == null) {
parent.kids = new ArrayList(2);
}
parent.kids.add(new WeakReference(this));
}
}
There are weak references, good. But wait – who’s cleaning up kids collection? Nobody? There we go…
This class is a joke. All important fields are private, it’s not implementing any interface, there is no simple way how to fix the problem. As a logger I wanted to get rid of myself when I’m finalized – no way, you can’t even call setParent(null), it’s gonna throw an exception and fail to do anything else. Saddest thing of all is that kids collection is not used anywhere for anything reasonable – it’s just sitting there eating heap. And you can’t do anything about it. Damn you, Sun.