Logging frameworks have become a standard part of projects, since Servlets and Log4J first emerged. But how should we log? Are we getting the most we can from it?
Many developers see logging & debugging as separate tasks. When confronted with a problem we set breakpoints, step through, inspect variables, and trace through loops – often finishing hours later..
Finding problems this way is hard. Does it have to be so difficult? Could there be a way to get right to the problem area, in just minutes? Sometimes without even needing to step through?
Logging can provide an answer.
I don’t mean just any logging. Far too much logging tells you “entering and exiting method”, dozens of irrelevant minor fields, obtuse variables, hundreds of lines of clutter hiding a very few useful facts amid their noise.
Logging that focuses on (and only logs) significant & useful facts will lead you straight to a problem. Just looking at the log prior to a stacktrace should tell you the situation & facts arising to the problem.
What request the user/application made.. what files or database records were being accessed.. important decisions made/ or actions performed in code.. every key detail, leading up to the fault.
If your logging produces this information, and (very important) doesn’t clutter the logs with irrelevant noise or non-useful detail — you will be in the enviable position of being able to quickly & easily find the source of most problems.
So, I hear you ask, what should an application log?
Good logging is based on a few simple principles:
Log “information”, not “data”
Logging provides us the means to capture vast reams of data – every single method visited, every minor field of every object. But this is exactly what we wish to avoid. With too much data, our ability to focus on, find or trace high-level information will be lost.
Information is what our log should contain, to provide an outline of what our application & data are doing. This should be a high-level outline capturing only the key facts, activity & decisions – all the rest can be filled in, between.
For example, the common logging pattern of “updateExtraCharges()”, “enter calcShippingMethod1()”, “leave calcShippingMethod1()” is entirely redundant if you instead log some simple facts: “place order: cust=8323, id=51507” and “shipping method: Fedex”.
The fact that placing an Order calls into (enters and leaves) various subsidiary methods is totally inferred from control flow, provided you log the business decisions that are being made & report exceptions properly.