structured/combined logging with Log4J

Question

Hi fellow geeks, I hope you can help me.

I have a web service that needs to log transactions. Since there are many hits, the log statements appears disjoint/fragmented in the log file.

I've considered passing a StringBuilder instance through-out the layers and appending the statements to this instance, then I log its contents once at the very end (finally clause in the main controller) before returning a response to the client. This seems unnecessary and I'm sure there's a cleaner way to do it with Log4J.

Can anyone shed light on the issue?

Thanks

Answer 1

You might consider turning the problem around: instead of consolidating all of the pieces of an entry when logging at runtime, consolidate them later during the analysis of the data.

For example, we have an application that logs a lot of data, where fast response is important. We recently implemented a (custom-built) system that logs to what is effictively a relational database. However, the logging portion of it is optomized for logging; we simply append tuple data to the logfile in the order that the application generates it. We have tools that can do queries against this format, and also plan to generate new versions of the database stored in a different format when we start getting annoyed that every query against the log format effectively requires a table scan of every table in the database.

Even if you can't make direct use of this technique, just considering it may give you ideas for doing something better within Log4J.

Answer 2

We needed to solve something similar in the past. We have created an enveloped message object holding also metadata about message (e.g. user transaction id) and a custom appender class. In this appender class we are using instanceof statement to get the metadata from the envelope instead just simply calling toString (which should return a nice log for general appenders).

Or you can consider using SLF4J and it's standard capability to pass Marker objects with log messages. E.g. see Javadoc for their debug(Marker marker, String msg) method overload.

Answer 3

the good things is that you are using Log4j. The library itself implements the concept of nested diagnostic context (org.apache.log4j.NDC) and mapped diagnostic context (org.apache.log4j.MDC). I reckon you should definitely have a look at both, because those allows you to build some sort of the context that you can use in your log output layout.

Answer 4

One more idea, instead of passing a StringBuilder instance through-out the layers, which might lead to pretty awkward API (additional method parameters), you could consider using java.lang.ThreadLocal to hold the current context that could be dumped to the log at the very end.

Answer 5

Do you really need to have all the log statements in order I mean they are being logged as they occur. If you change the order you might miss the sequence of some events which you may need to track down tricky bugs.

Can you not add an identifier to your messages like start them with a thread id or user id from which the request is originating, this way you can then run queries on the logs using something like grep.

grep userId *.log

the statement will return all the log statements for that user in the correct order and its fast.

We use this technique on a high throughput trading platform and it is the easiest way of following a trade or user request through the system in the log files. It also doesn't require extending or writing your own logger.