One would like to assume that turning logging on would have no side effect on the running software.
LOGGER.info("The current session is {}", request.getSessionId());However, there are always ways in which logging can cause more work, or even a state change. In the above, let’s say the getSessionId needed to pull the session id down through the request from some sort of session storage. We might find that the effect of logging is to pull more data into memory, or to exert load on the database.
In this instance, the logging statement happens every time, so it’ll be consistent, even if it’s more effort.
What if the logging statement used lazy loading to fulfil parameters, avoiding the extra effort if the logging level wasn’t set to include that sort of output?
LOGGER.debug("The current session is {}", () -> request.getSessionId());We’ve added protection that the effortful thing only happens when needed, but we’ve also now got a secret side-effect of logging being on.
None of this is technically wrong… but recently I encountered a strange problem where the logging level was required for an algorithm to work! This was where a hidden side effect of logging was getting embroiled in an algorithm. Ick.
public Object decode(Request request) {
if (request.getBody() != null && request.getLength() != null &&
request.getLength() > 0) {
return customDecode(request.getBody());
}
return super.decode(request);
}This handled a web request and intended to apply some custom parsing to the body if it was present, otherwise defaulting to the super class’s default handler.
It worked when logging was on, but didn’t work when logging was turned off.
Why?
In this instance, the request object behaved differently after logging. In the case of logging, the request body was loaded into memory from the input stream. Then it was output to the console. Then the data was turned back into a byte array stream and passed to the handler.
If logging was off, then the original input stream was passed to the handler.
Guess what. In this case, a normal input stream doesn’t know its length. It just knows when to say it’s finished.
So the side effect of logging was to make the object more amenable to the custom code’s length check. It’s a weird outcome of logging, yet it’s understandable. We can’t observe the stream any other way than loading it, then repackaging it for the other code. However, it’s also a bug waiting to happen.
The moral of the story. Beware logging… it can sometimes have subtle side effects.
Published on Java Code Geeks with permission by Ashley Frieze, partner at our JCG program. See the original article here: Logging Side Effects Opinions expressed by Java Code Geeks contributors are their own. |
