Wednesday, July 14, 2010

Intent Based Logging

Does your log message tell a story? Does it have enough context to help you understand the use case and code flow that caused the execution to flow at the given point? In one of our projects, we are experimenting with something I like to call "logging with intent". So what I mean by intent is that, at critical points in the code (entry point, significant fork points, significant intermediate points, etc.), you record the intent of what your code is doing. The implementation of this can choose to use any programming construct that makes sense (we ended up using Thread Local variables for our Google App Engine based project). But the basic concept is that you keep adding "intent breadcrumbs" along the way. Now when it is time to log a critical event (such as a warning or severe or error log), in addition to printing the specific log message, you also print the "intent trace log". So you see the log message, you also get additional context as to what the code was trying to do. Now you could use AOP or other byte code manipulation technique to add intent for every entry and exit point for every method call... but I think then it becomes too fine grained and mechanical (and there may be cases where that is useful, but there are other ways to achieve it rather than making it so pervasive). I am going to track how useful this is in real world in our application and make tweaks as necessary. I will blog about it if I end up making significant changes to the current approach.