Log And Throw

Log And Throw

1 Kommentar zu Log And Throw

jQAssistant can be used to find antipatterns very efficiently in existing code bases. One nice example is „log and throw“:

try {
  ...
} catch (AnyException e) {
  LOGGER.error("Something very suspicious happened.", e);
  throw new OtherException(e);
}

The snippet catches an execption, logs it (including the stack trace) and creates a new exception which then is thrown.

The problem with this approach is that the exception will be caught somewhere else and logged again – so the full information ends up in the log files at least as many times as this pattern is repeated within the call hierarchy.

In other words: log files become bloated with redundant information which makes them very hard to analyze.

Logging At Boundaries

Therefore the recommended way to go is to „either log or throw“, thus an exception will always be logged exactly once.

In general it’s a good idea to let exceptions which cannot be handled „bubble up“ through the call hierarchy and implement handling mechanisms on the „boundaries“ of the system. Here everything gets caught, logged and furthermore specific actions are executed which correspond to the technical nature of the boundary, e.g.

– a UI may present an error message to the user
– a REST service should return an appropriate status code to the client

Frameworks (e.g. JAX-RS) often provide generic handlers for these purposes.

Finding The Antipattern

Coming back to „log and throw“ the question arises how this anti-pattern can be detected using jQAssistant. First we need to find points in the application where exceptions are thrown. Sadly this information is not directly available in the data model but we have a simple workaround: we can look for invocations on constructors of exception types. The second step is to identify invocations of logger methods which take „Throwable“ as (last) parameter and which are co-located to the before-mentioned pattern within a defined range of line numbers, e.g. „4“:

// 1. Identify all methods that invoke a constructor on an exception type
MATCH
  (exceptionType)-[:DECLARES]->(constructor:Constructor),
  (method:Method)-[newException:INVOKES]->(constructor)
WHERE
  exceptionType.fqn =~ ".*Exception"
WITH
  method, newException

// 2. Find all log invocations with a Throwable parameter that are co-located to creating Exception instances within a distance of max. 4 lines
MATCH 
  (logger:Type)-[:DECLARES]->(logMethod:Method)<-[log:INVOKES]-(method)
WHERE
  logger.fqn = "java.util.logging.Logger" // Java Util Logging (JUL), replace with your logging framework
  and logMethod.signature =~ ".*,java.lang.Throwable\\)"
  and abs(log.lineNumber - newException.lineNumber) <= 4
WITH
  method, log

// 3. Find the declaring type for each detected suspicious method and return the result
MATCH 
  (type:Type)-[:DECLARES]->(method) 
RETURN
  type.fqn as DeclaringType, log.lineNumber as LineNumber
ORDER BY
  DeclaringType, LineNumber

At a first distant glance the query is quite complex. After taking a closer look we see that it actually consists of the described two parts and an additional third one. The latter just prepares information for the result to be returned (i.e. the Java type and line number).

Let’s try it on the Java Runtime Enviroment:

jqassistant.cmd scan -f <path to JRE>/lib/rt.jar
jqassistant.cmd server

After opening the browser (http://localhost:7474) and executing the query we see the following result:

Query Result for Log And Throw

The first entry is „com.sun.jmx.mbeanserver.JmxMBeanServer“, let’s have a look at this class within the IDE:

JmxMBeanServer

Got ya!

About the author:

@dirkmahler

1 Comment

Reply Cancel

Back to Top