307 Temporary Redirect

I'm trying out Jekyll in GitHub pages at http://sergiofagostinho.github.io/.

The entropy of logging

A couple of weeks ago, my colleague António Vieira made an internal presentation called the “The entropy of logging”. In this post I share the main points of the presentation and my thoughts on the subject.

Logging

"Event logs record events taking place in the execution of a system in order to provide an audit trail that can be used to understand the activity of the system and to diagnose problems. They are essential to understand the activities of complex systems, particularly in the case of applications with little user interaction (such as server applications)." - Wikipedia

We all know what logging is but how to do it right?

 Some guidelines might help…

 Relevant

Captain's Log, Stardate 43125.8. We have entered a spectacular binary star system in the Kavis Alpha sector on a most critical mission of astrophysical research. Our eminent guest, Dr. Paul Stubbs, will attempt to study the decay of neutronium expelled at relativistic speeds from a massive stellar explosion which will occur here in a matter of hours.

Irrelevant

Captain's Log, Stardate 43125.8. Today I had baked beans for lunch. Lt Commander Data didn’t understand my irony. Lt Commander La Forge has the feeling unwell, probably the galactic flu.

Levels

7 guidelines

1. Log relevant events
2. Log the unpredictable
3. 1 event = 1 log line
4. Log the boundaries of the application
5. Consistent and parsable
6. End-to-end traceability
7. Protect privacy

Should libraries include logging?

No! Logging is an application level concern
Libraries should expose all the relevant state as return values, exceptions or event listeners.
If you really need events on your library keep it very simple and plugable.

My (Sergio) conclusion

Logging is something that many of us, professional developers, take for granted. In every project I've worked, as soon as deploy an application to an environment, things start to fail (which is expected), but it’s rare that the existing log is enough to quickly debug the problem. Most often, critical information is missing, and the existing log entries are mostly just clutter.

Based on my experience, all of these guidelines are valid. The ones I hadn't applied in the past were point 3, as well as point 5 and 7, but simply because they didn't apply to my application's domain.

Having one log entry per event may seem strange at first because it seems a strong constrain, but I've recently have been applying it, and it has actually made the code cleaner. Basically, each domain event will produce a single log entry in case of success (INFO), or in the case of failure (ERROR)To me it feels the correct approach, particularly for a Domain Driven Design approach (although I haven't been using it currently), as you should have one log entry per domain event. Having that said, this shouldn't be applied too literally: it's still OK to have a random log entry at the DEBUG level, just not at INFO and ERROR (you are filtering DEBUG entries in production, right? :))

By applying the single log entry guideline, you'll probably have to log a lot of information, which leads to the parsable guideline. In our current development, we've found that the best approach is to log it as JSON. We are not constraining the event to an actual schema, although we try to be consistent. In practise, this means we are using Json.NET to serialize a dynamic object (in .NET), or Jackson to serialize an HashMap object. Log parsing tools (such as logstash) should have any problem with this.

Regarding privacy, we have been very careful. We try to use SecureString (in .NET) or char[] (in Java) types for holding passwords in memory, but for the remaining data the best approach is to remove sensitive fields from serialization (preferably in a declaratively form, to be clear about this in the code). When the sensitive information is relevant for logging issues, the standard approach is to log the first N characters of the text, and add place-holders (such as the asterisk character) to the remaining text.

Finally, regarding on the point of not logging on libraries, I can't say I totally agree with António. I mean, I agree if the library is a thin layer, such as in an infrastructure layer library; but this may harder to implement if the library is complex, such as a domain layer library (as I have implemented in the past). What I can add is that we should avoid logging in libraries if we possible; if not,we should use a logging framework facade, such as CommonLogging in .NET or SLF4J in Java, to reduce the change of friction.

Thanks to António Vieira for the interesting discussion and allowing me to share some of the content of his presentation.

Checked exceptions in Java

In this post I describe some issues I had with checked exceptions in Java, and my current approach to handle them.

When I developed in Java non-professionally some years ago, I found the checked exception mechanism interesting. The possibility to add to a method's contract the exceptions it throws, and therefore enforce that they are handled at compile seemed a good idea. (I actually missed them when I first started developing in C#). Now that I a more experienced developer and that I try to apply the SOLID principles, I'm not so sure.

Dependency Inversion Principle

When you are applying the Dependency Inversion Principle, classes depend on interfaces, not the actual implementations. Let's say you have a Serializer interface with a single serialize() method and SerializerImpl class. So if SerializerImpl has a serialize() implementation which throws an exception, then Serializer must also declare it throws that exception on serialize(). It seems to me a bit awkward that the interface must know which exceptions the actual implementation throws, but that doesn't seem to break any SOLID principle too much, so I can live with that.

What happens when you need to have must implementations of that class? Let's say you need to implement an XML, a JSON and a Protobuff serializer. Each serialize() implementation will probably need to declare the exceptions it throws. For simplicity sake, let's say XmlSerializer throws XmlException, JsonSerializer throws JsonException, and ProtobuffException (in reality, depending on the framework you use in each of the implementations that may need to throw more than on). But then, the Serializer interface must also declare it throws the exceptions each implementation throws, which mean that each implementation must know all the exceptions the other implementations throw. That means that all the Serializer implementation are coupled with each other, and the interface is coupled with each one of the implementations. This definitely doesn't seem right!

So, my approach was to introduce a new exception: SerializerException and change the serialize() method to throw only this exception. The purpose of this exception is to wrap the actual exceptions thrown by the frameworks used for each of the serialization methods. It adds the extra work of having to define a new exception, but it decouples the Serializer from all the implementations, and decouples each implementation from all the others.

Checked or unchecked?

While this approach seems good, it's only elegant for simple applications, that is, if your application entry point invokes the Serializer. If you have a non-trivial application with a more complex dependency tree, and you just want to handle exceptions at the high-level, then it becomes cumbersome. Let's say you entry point class invokes a method foobar() in class Foobar, which invokes a method foo() in class Foo, which then invokes a method bar() in class Bar, which finally invokes serialize(). All these methods: foo(), bar() and foobar() must declare that they throw SerializerException, regardless of their responsibility. Also, if you have unit tests for these classes, then each test method must also declare it throws SerializerException.

My approach was to make SerializerException extend RuntimeException instead of the (checked) Exception. This means that the Serializer interface (and any implementation) no longer need to declare it throws any exception, so the code becomes much simpler. However, I did document that the method throws the exception using the @throws javadoc comment. (This is pretty much the approach used in C#).

As a I did this, I did do some research. Oracle's documentation on the matter (Unchecked exceptions - the controversy) didn't convince me, and lot of people shared my opinion, but none of them was quite an authority. Then I found Bruce Eckel's book "Thinking in Java" (4th edition). Namely in Chapter 9, section "Perspectives", page 347, he has a similar opinion to mine (and so does Martin Fowler).

Conclusion

In my opinion, avoid checked exceptions in Java unless you are doing a trivial application. If you need to work with checked exceptions, wrap them in your own unchecked exception. The extra work needed outweighs the clarity and decoupling you obtain in your code base. Nevertheless, documenting these exceptions in javadocs and properly (unit) testing your code is also necessary,