Category Archives: Programming

Best practices for FindBugs in new projects

I have been testing FindBugs effectiveness and ease of use in an existing project, DirectJNgine, a small 7000 lines project. With this experience in hand, I have arrived to a small set of preliminary best practices and recommendations for new projects.

Turn all settings to the max

  • Set Analysis effort to Maximal.
  • Check all detectors, except those with the “TEST” pattern.
  • Set Minimum priority to report to Low.
  • Check all reported bug categories, except Bogus random noise.

Tip: only deactivate FindBugs real-time analysis if it noticeably slows down your development (i.e., if it breaks your train of thought, it is bad; if it is just a little nuisance you will probably survive). If you do, make sure you run the analysis manually often.

Never commit source code if there is any warning

This is so important I’ll repeat it:

  • Do not commit source code if there is any outstanding FindBugs warning.

Always have an automated check process for FindBugs

  • Make running FindBugs part of the “pre commit to version control system” process.
  • Make running FindBugs part of your Continuous Integration system. Make it fail if there is any warning.

Use the Nullability Annotations extensively

  • @NonNull: mark parameters, method return values and fields that must not be null (for fields, we refer to being null after construction).
  • @CheckForNull: mark parameters, method return values and fields that might be null.
  • Set the following default annotations for packages (use
  • @DefaultAnnotationForParameters(value=CheckForNull.class)
  • @DefaultAnnotationForFields(value=CheckForNull.class)
  • @DefaultAnnotationForMethods(value=NonNull.class)

Use the Resource Management Annotations

  • @CleanupObligation: mark resource manager classes.
  • @CreateObligation: mark the constructor(s) that acquire the resource(s).
  • @DischargesObligation: mark the method(s) that release the resource(s).

Use the @CheckReturnValue annotation

Annotate those methods that:

  • Return diagnostic info or other data that should never be ignored by the caller.
  • Belong to immutable classes, and return a new object that is the result of applying an operation that would otherwise end up mutating the original object.

Handle warning supression with care

  • Warnings are your best friends: do not disable them unless you really must.
  • If you have to disable a certain kind of warning, do that globally: never use the @SupressWarnings annotation.
  • If you have to use the @SuppressWarnings annotation, check twice that you are 100% sure that’s what you really need.
  • If you use SuppressWarnings, always write the reason in the justification attribute. If you can’t write it in a way that makes you feel good, then you should probably not supress the warning.

Recommended warning supression

Warnings to supress globally on a per-project basis:

  • InefficientMemberAccess.

Other issues

  • Use the FindBugs plugin for your current IDE.
  • If you use the Eclipse plugin, take into account that it will not issue some kinds of warning just because you save a file: you will want to perform global checks periodically.

FindBugs: better default values for Nullability Annotations

One of the nicest features in FindBugs is its support for annotations indicating whether a certain value is nullable or not, and the way it uses that information to perform additional checks.

There are three annotations: @NonNull, @CheckForNull and @UnknownNullnes.
By default, FindBugs assumes that method parameters, method return values and fields are annotated implicitly with @UnknownNullness.

But, to me, the best policy is:

  • For method parameters: use @CheckForNull.
  • For method return values: use @NonNull.
  • For object fields: use @NonNull.


Easy. We are trying to follow this principle: give as much as as you can, demanding as little as possible -in a safe way.

For method parameters, the worst case is receiving a null value, because your code will need to be careful and check for null if it uses the value in any meaningful way. Therefore, we should use @CheckForNull by default because this demands less from our code users.

For method return values, life will be easier for our code users if they need not care about a returned value being null. Therefore, use @NonNull to give as much as you can.

For object fields, things are not that clear cut, because they do not affect the user (directly), as they should be private. I just chose to make them @NonNull because I feel this is the safest policy.

Of course, these are the “ideal” settings: you will have to provide an override from time to time, annotating an element explicitly with a different annotation.

How to do this?

You can provide the desired default annotations for a package by adding the following annotations to

@DefaultAnnotationForParameters( value=CheckForNull.class)
@DefaultAnnotationForFields( value=CheckForNull.class)
@DefaultAnnotationForMethods( NonNull.class)

Really neat!

If you start using these annotations with FindBugs, you will be surprised by the clarity they add and the way they can help diagnose null values misuse.

Taking a look at FindBugs in a real project: checking DirectJNgine

I have been testing FindBugs effectiveness and ease of use in an existing project, DirectJNgine. A small project, 5.600 Java lines, plus 2.000 Javascript lines.

First conclusions

With all settings set to the maximum strictness, FindBugs reported 70 issues. Do not get alarmed, though! Issues are things FindBugs thinks you should check, not necessarily bugs.

In fact, only one of these issues ended up being a bug, one that would happen once in a lifetime -but it was a real bug.

The experience was very positive: in fact, I never found a diagnostic I disagreed with. And, in a few cases, FindBugs pinpointed code that I just did not know could be suspicious.

In many cases, FindBugs reported performance issues that, I knew beforehand were absolutely irrelevant, but would have been a serious problem in a different context.

That said I converted all code to the better performing version, if only to make FindBugs happy.

Now, this is very important: I strongly believe you should never commit code with outstanding warnings or issues to your version control system. This destroys credibility and trust.

Another way to say this is do not live with broken windows… Yes, sometimes you will have to do some extra work just to please FindBugs, but I think this will pay off later.

Back to FindBugs, in 80% of the cases the diagnostic explanation allowed me to “fix” the code directly.

When that was not the case,  it provided me sufficient information to let me find the way to fix the problem with ease.

To be fair, the only “poor diagnostic” case I found was for circular class dependencies!

Of all checks performed by FindBugs, I disabled only the checks for circular class dependencies (two cases), and only because FindBugs is a stable and mature project with a published API I am committed to support. In an ongoing project I would probably have fixed that.

For issues I did not want to “fix” (because I considered that the issues were not real problems, and the “fix” was too convoluted or impossible), FindBugs provided me with the @SuppressWarnings annotation -which you should use scarcely!

All in all, making FindBugs happy was not difficult, enhanced my code in some cases, helped me uncover and fix one bug, and only in a few cases got in the way. And all of this setting it to the maximum strictness. A really good balance sheet!

Feasibility of a “cleanup campaign” for existing projects

Of course, you will need to make especial provisions if you want to introduce FindBugs in an ongoing project, unless you are prepared to launch a cleanup campaign that ensures your application has zero issues and uses FindBugs annotations (more on that later!).

Now, I have to say that the full cleanup campaign for DirectJNgine, with all settings set to the maximum strictness (!), took arount 10 to 12 hours, which I think is very little time.

If you take into account that I had to learn FindBugs way too, I’m quite sure that would have taken 6/8 hours if I had to do it now in a similar project.

Use FindBugs annotations -really!

Most people seem to be using FindBugs to check their code, but they seem not to be using FindBugs Annotations to help it diagnose even more problems.

Too bad, for these annotations are hidden gems. Use them! They will help FindBugs to check for adequate resource cleanup, correct null handling, etc. I have discussed them in other articles and posts about FindBugs.

My experience “porting” DirectJNgine to use these annoations was straightforward: 70 minutes only!

To be fair, I’m sure that was partly due to the fact that I have near 500 assertions in DJN. Many of these are checks for nulls,and that helped a lot when trying to make sure whether values were nullable or not.

While I do not expect most programs to be “ported” so easily, I don’t think it will take too much time.

That said, and even though I’m almost paranoid with checks for null values, FindBugs found two places where I had forgotten to assert that a value could not be null. So, again, a good result.

The Eclipse plugin

The Eclipse plugin for FindBugs works quite well. However, you need to know that some kinds of checks are not performed automatically when you save the source code.

Therefore, for some kinds of issues, you will need to manually run the FindBugs checker or rebuild the whole app. This happens only for some kinds of issues, and in most cases having real-time checking works and is useful, so not much of a problem if you are aware of this.

One caveat, though: DirectJNgine is a small project, so maybe FindBugs will be more taxing for medium to big projects. I’ll report on this when I introduce FindBugs in bigger projects.

On closing

FindBugs is an excellent and unobtrusive tool, worth using. In fact, I just hope the compiler could provide many of its checks as warnings.

FindBugs: make your code better with Nullability Annotations

Handling null values is not that easy. For example, there are scenarios in which null values will never happen: this makes code checking whether a value is null not only unnecessary, but misleading -because it creates the wrong expectations.

However, in other cases, a null value might happen, and we should test for this before using it -unless we are happy when with null related exceptions are raised.

Sadly, the fact is the Java compiler will not provide help with this. But all is not lost: FindBugs provides several annotations that might help, especially because it can perform some code analysis that will detect potentially dangerous or unnecesary code.

Null checks

There are three scenarios when it comes to non-primitive values: you assume that values can’t be null, you assume that they can…or you assume nothing. FindBug provides us with three corresponding annotations: @NonNull, @CheckForNull and @UnknownNullness.

A quick example

Let’s take an in-depth look at this class:

public static class NullHandling {
  public String value;
  public int getValueLength() {
    return this.value.length();
  public String myToUppercase( String parameter )
    if( parameter == null )
      return "";
    return parameter.toUpperCase(Locale.getDefault());

  public String getValue() {
    return this.value;
  public void justUseGetValue() {
    int length;
    if( getValue() == null )
      length = 0;
      length = getValue().length();
    System.out.println( "Value length: " + length);
  public String justUseMyToUppercase() {
    return myToUppercase(null);

Let me pinpoint some potential problems in this code:

  • If the value field can be null, then this.value.length() in getValueLength will bomb.
  • If getValue can’t return a null value, then code using it (as justUseGetValue does) need not check for null values and can be simpler.
  • If parameter can’t be null in myToUppercase, checking for it is unnecesary -and misleading.
  • If myToUppercase can’t receive a null parameter, then calling it the way justUseMyToUppercase does is a bug.

Well, we are not short of potential problems or unnecesary code, but the compiler remains completely mute. And this is only logical, because there is no way to tell the compiler about the nullability restrictions for fields, parameters or method return values.

Now, let’s use FindBugs annotations to provide clarity and helpful diagnostics, if only for illustative purposes.

As a first change, let’s pretend that the value field might be null. To that end, we need to annotate it with @CheckForNull as follows:

public String value;

This causes a warning to be issued by FindBugs for the following code:

public int getValueLength() {
  return this.value.length();

Effectively, this.value migth be null, and therefore calling this.value.length() in getValueLength without checking whether it is null is not something I would recommend.

Here is a better implementation of getValueLength, which makes FindBugs happier:

public int getValueLength() {
  if( this.value == null )
    return 0;
  return this.value.length();

Now, let’s pretend that myToUppercase can’t be called with a null value, as declared in the following code:

public String myToUppercase(
@NonNull tString parameter )

This causes FindBugs to report two issues. The first one in myToUppercase, because we are checking whether parameter is null, when that should never happen.

To solve this, we just remove the null check, leaving the method body as follows:

return parameter.toUpperCase(Locale.getDefault());

The second issue is reported in justUseMyToUppercase, which was calling myToUppercase passing a null value, something illegal: the fix is to pass it a valid value.

We have seen examples of nullability annotations for fields and method parameters: let’s see such an annotation for a method, so that we have an example of each possible usage of these annotations. To that end, we will pretend that getValue just can’t return a null value, as follows:

public String getValue() {
  return this.value;

That makes FindBugs complain, because this.value might be null, and in that scenario getValue will be breaking the guarantee. We can fix getValue by checking for this.value being null as follows:

public String getValue() {
  if( this.value == null )
    return "";
  return this.value;

FindBugs will complain about justUseGetValue (which I made rather convoluted on purpose!), because it is checking for getValue returning null when it just can’t do that. The fix is as easy as rewriting justUseGetValue as follows:

public void justUseGetValue() {
  int length = getValue().length();
  System.out.println( "Value length: " + length);

I think that these examples illustrate quite well the usefulness of explicitly declaring whether a field, method parameter or returned value can be nullable or not, and how things can go wrong in subtle ways when you choose to ignore the issue (the default case for Java code).

By the way, I want to mention the fact that I have made all code self contained in a class to make code shorter and easier to understand: however, FindBugs will make checks when external code uses fields, parameters or methods with nullability annotations. This is very interesting, because users consuming our code will probably know very little about our assumptions: annotations and the ability to check them will be even more valuable in that scenario.

What to annotate: method parameters, fields and method results

Our examples have shown all places where these annotations can be placed: in fields, method parameters and method results. The only thing worth mentioning is the fact that, for fields, @NonNull just means the fields will never be null after construction, whereas @CheckForNull means they can be null after construction.

And, of course, for methods the annotation refers to the returned value.

The @Nullable annotation

I have to make a little confession: FindBugs provides an additional @Nullable annotation too. I haven’t discussed this one because, as far as I know, this annotation has no well defined semantics: see the discussion at, or, for example.

For the time being, just ignore it unless you want to make your life more difficult:@CheckForNull and @NonNul seem to be more than enough.

And, of course, if somebody out there knows better, I’ll be glad to hear from him!

Other issues

I’m a fervent fan of Java assertions, and I write assertions checking that a parameter is not null so often that it has become part of the landscape in my projects. Granted, we’ve got the FindBugs @NonNull annotation, but I still want to write an assertion that checks the parameter is not null.

Why? Because I might be writing my code in an environment where FindBugs is not used, and they might refuse my request to add the required jars for compile time only –stuff happens!

I have verified that FindBugs will ignore the attempt to check for a value being null in an assertion, making it possible for me to have both things: the annotation plus FindBugs checks, and the assertion. Therefore, this code will compile and pass FindBugs checks.

public String myToUppercase(
@NonNull String parameter )
assert parameter != null;
return parameter.toUpperCase(Locale.getDefault());

And, just for completeness: there is a fourth annotation, @PossiblyNull, which is deprecated –and equivalent to @CheckForNull.

Following a strict policy

I hope the prior examples have shown that there are many subtle issues with regard to null values handling and that FindBugs makes handling them a breeze.

Therefore, I would advise a very strict policy: add @CheckForNull and @NonNull annotations to all fields, parameters and methods handling non primitive types. To be fair, I find this so helpful that I feel you should never have a I can’t assume anything about nullability policy in our own code, unless there is some really good reason.

Besides, it might be very interesting to set the default policy to @CheckNotNull or @NonNull, something you can do at the package or class level using one or more of the following annotations: @DefaultAnnotation, @DefaultAnnotationForFields, @DefaultAnnotationForMethods, @DefaultAnnotationForParameters or @ReturnValuesAreNonnullByDefault.

For example, this code sets @NonNull as the default policy for MyClass:

public class MyClass {
// ...

It is possibly to set the default policy for all classes in a package too.

In fact, several papers suggest that the non-null policy should probably be the default one for Java, because “the authors conducted an empirical study of five open source projects totalling 700 K lines-of-code, which confirms that, on average, 75% of reference declarations are meant to be non-null, by design” (see Reducing the use of nullable types through non-null by default and monotonic non-null), or

Tool and library versions

The FindBugs version we have used for this article is 1.3.9, with the corresponding plugin running in Eclipse 3.3.0.

By the way, note that, to use these annotations, you need to add a pair of jars FindBugs provides: annotations.jar and jsr305.jar. However, these jars need not be redistributed, they are used at compile time only.

Related articles

You might be interested in taking a look at other FindBugs posts and articles:

  • This article is about using FindBugs annotations to make sure that resources (connections, streams, sockets, etc.) are released.
  • This article is about using the FindBugs @CheckReturnValue annotation to make sure programmers consuming our methods use the returned value for some of them.

FindBugs: make your code better with the CheckReturnValue Annotation

I decided to take a look at FindBugs recently, and used my DirectJNgine project as a testbed. Even though torture testing DJN with FindBugs made me make some changes to it, I just found a bug (thankfully, one that will arise so rarely I doubt any DJN user will ever come across it). Here is the code:

if( logger.isDebugEnabled() ) {
  logger.debug( "Api file deleted: '" + file.getAbsolutePath() + "'");

And here is the fix:

if( !file.delete() ) {
  throw new IOException( "Unable to delete " + fullFileName);
if( logger.isDebugEnabled() ) {
  logger.debug( "Api file deleted: '" + file.getAbsolutePath() + "'");

I just forgot to check the value returned by delete, because I assumed inadvertently that file.delete would raise an IOException. But it just returns a boolean value telling you whether it succeeded or not. Uh, oh!

Fortunately, FindBugs check for this, and helped me find the bug.

Now, wouldn’t it be nice if there were a way to tell FindBugs that users of a certain method you have implemented should never ignore the return value?

And, indeed, there is a way to do that: just annotate the method with @CheckReturnValue, as follows:

@edu.umd.cs.findbugs.annotations.CheckReturnValue( explanation="...")
public String methodWhoseReturnValueShouldNeverBeIgnored( String value ) {
  return value;

Now, if you call this method without using the returned value, as follows,

public void useMethodWithCheckReturnValue() {
  // FindBugs warning: you are ignoring the returned value!
  methodWhoseReturnValueShouldNeverBeIgnored ("a value");

then FindBugs will complain.

Now, I can think of two main scenarios where you should annotate a method with @CheckReturnValue:

  • The method performs an operation for which it is very important to check the result because it indicates success or failure, and your code will probably need to handle these scenarios differently. This is the“forgot to check the result of delete” scenario that caused the bug in DJN.
  • You applied an operation to an immutable object, and are returning a new object that is the result of applying the operation to the original unmodified object: it is clear that you must use the returned object from then on, instead of continue using the old unmodified object. For example, most operations on BigDecimal should probably have this annotation.

Using this annotation is so easy that you should probably add it to your programming arsenal.

Tool and library versions

The FindBugs version we have used for this article is 1.3.9, with the corresponding plugin running in Eclipse 3.3.0.

By the way, note that, to use these annotations, you need to add a pair of jars FindBugs provides: annotations.jar and jsr305.jar. However, these jars need not be redistributed, they are used at compile time only.

Related articles

You might be interested in taking a look at other FindBugs posts and articles:

  • This article is about using FindBugs annotations to make sure that resources (connections, streams, sockets, etc.) are released.

FindBugs: make your code better with Resource Management Annotations

FindBugs is a nice tool that helps finding problematic areas in your code. But, not only that: it provides several annotations that you can add to your own code to make it easier to use in a robust way, by helping FindBugs pinpoint potential problems when other programmers use it.

Several of these annotations are intended to help catch a very common error with resource handling: forgetting to call cleanup methods, such as the proverbial close. Too bad that these annotations are not documented in the FindBugs manual: I hope this post contributes to make using them easier.

Diagnosing missing cleanup

Sometimes you create classes that handle expensive resources. For those classes, you should probably perform cleanup as soon as you have finished using the resource, exactly the same way you need to call a cleanup method for a JDBC Connection, a Stream, sockets, etc.

There is a hidden gem in FindBugs that allows you to annotate your own resource classes so that, if you forget to call their cleanup method, it will flag the mistake.

Note that, to use these annotations, you need to add a pair of jars FindBugs provides: annotations.jar and jsr305.jar. However, these jars need not be redistributed, they are used at compile time only.

The following class, ResourceClass, uses the @CleanupObligation, @CreatesObligation and @DischargesObligation annotations in FindBugs to provide that functionality:

public static class ResourceClass {
  public ResourceClass() {
    // Do nothing: just for illustrative purposes

  public void doCleanup() {
    // Do nothing: just for illustrative purposes

First of all, you annotate the resource class with the @CleanupObligation annotation. This makes it clear that the class manages a resource that will need to be release.

Secondly, you need to specify which is/are the method(s) or constructor(s) that acquire the resource: you just annotate them with @CreatesObligation.

Thirdly, you need to specify which is/are the method(s) that perform cleanup, using the @DischargesObligation annotation. That’s it!

Let’s see what happens when FindBugs sees code that acquires the resource but forgets to perform cleanup, such as this:

public void handleResourceForgettingCleanup() {
  // FindBugs warning
  // Method ...handleResourceForgettingCleanup() may fail to clean up...
  new ResourceClass();

This sample code acquires a resource, as it invokes the constructor marked with @CreatesObligation, but it forgets to call the corresponding cleanup method –doCleanup, marked with @DischargesObligation. When checking this code, FindBugs pinpoints the issue as follows (in Eclipse):

FindBugs Resource Handling Annotations Error Message

Neat, huh? Once the code is corrected, as shown in the following code, FindBugs will not complain anymore:

public void handleResourceWithCleanup() {
  ResourceClass resource = new ResourceClass();
  try {
    // Just use resource in some way to please our very demanding compiler
  finally {

This is a very nice thing, but apparently FindBugs does not perform inter-procedural analysis for this, so this will not be diagnosed correctly in a complex scenario.

No problem. I think that the annotations would be useful even if they were used to document only. The fact that they help FindBugs diagnose wrong code nine out of ten times just makes it better.

But I’ve got a false positive!

Well, yes, false positives can happen: FindBugs is good, but not perfect.

The simplest solution is to add a @SuppressWarnings annotation to make FindBugs ignore the issue. I will not discuss that annotation here, as it deservers more time than what I have available right now.

Be careful, for there is a FindBugs specific @SuppressWarnings annotation, which is different from @java.lang.SuppressWarnings: don’t mix them!

Tool and library versions

The FindBugs version we have used for this article is 1.3.9, with the corresponding plugin running in Eclipse 3.3.0.

DirectJNgine 1.2 final is out

Today I am releasing DirectJNgine 1.2 final. You can download it from

For detailed info, check the User’s Guide, which has been updated and has additional chapters devoted to the new functionality.

New in DJN 1.2: Support for stateful actions
It is possible to have session and application scoped actions, that will remember their state between requests.

To make an action stateful, use the @ActionScope annotation.

Take a look at the new chapter in the User’s Guide to get more information about stateful actions.

Sample code:

public class SessionStatefulActionTest {
  int count;
  String value;
  // ...

Once the SessionStatefulActionTest action is declared to be session scoped, it will be stored in the user session: this means that its count and value fields will be remembered across request belonging to the same user session.

New in DJN 1.2: Support for accessing the current session, etc. from within action methods
Now it is possible to get access to the current session, servlet context, servlet configuration, etc., from within action methods.
To do that, just use the new WebContext and WebContextManager classes.

Take a look at the new chapter in the User’s Guide to get more information about WebContext.

Sample code:

public WebContextInfo test_webContext() {
  WebContext context = WebContextManager.get();
  HttpSession session = context.getSession();
  ServletContext application = context.getServletContext();
  // Keep a counter of how many times we have called this method
  // in this session
  Integer callsInSession=(Integer)session.getAttribute("callsInSession");
  if( callsInSession == null ) {
    callsInSession = new Integer(0);
  callsInSession = new Integer(callsInSession.intValue() + 1);
  session.setAttribute("callsInSession", callsInSession);

  // ...

You will probably find that using session/application scoped actions might be an easier way to accomplish your goals, though.

New in DJN 1.2: Support for multiple action instances
Now that actions can be stateful, it makes sense to have more than one action instance for a given Java class, each instance manging its own state.

Other additions/improvements

· All bugs reported against DJN 1.1 have been fixed.· We have added more tests, including those needed to ensure bug fixes work: we have crossed the one hundred automated tests barrier!

· We have moved to ExtJs 3.1.1 for testing to ensure that we remain up to date. While 3.1 and 3.0 should work fine, the “officially” supported version will be 3.1.1.

· Licensing has been “fixed”: we are LGPL v3 -the way it was intended to be from the beginning.

Code breaking changes
· The programmatic API has been modified so that poll methods belong to actions, instead of being global. This was a must to support stateful actions.

· The suggested workaround for handling “\n” and “\r” characters in DJN 1.1 does not work anymore: instead you should pass them “as-is”.

Tested browsers
· Internet Explorer 8 (8.0.6001.18702)

· Firefox 3.5.6 (Gecko 20100115)

· Safari 4.0.4 (531.21.10)

· Google Chrome

To all, thank you for your encouragement and criticism: I hope this new release of DJN helps you make bettter software.

Hibernate SQL Logging: log4jdbc / Haciendo log de SQL con Hibernate: log4jdbc

This is the second part of Hibernate: logging SQL.

Using log4jdbc instead of Hibernate SQL logging

Hibernate logs a lot of information we can exploit to get the SQL is it generating in the end. That said, I miss some things:

•    Get the SQL prepared statements with the parameter values right there, instead of getting each parameter in a different log line.
•    Know how much time it took to execute every SQL statement (sigh!).
•    Know what line in my code caused the SQL statement to be executed (not the line in Hibernate’s code)

Now, what if we could get this log,

DEBUG: jdbc.sqltiming - " com.softwarementors.hibernate.util.DataAccess.persistAll(
1. /* insert com.softwarementors.demo1.Article */
insert into Article (id, version, currentPrice, name) values (null, 0, 27.2, 'Article_1')  {executed in 15 msec}"

instead of this one?

DEBUG: org.hibernate.SQL - "/* insert com.softwarementors.demo1.Article */
insert into Article (id, version, currentPrice, name)
values (null, ?, ?, ?)"
TRACE: org.hibernate.type.IntegerType - "binding '0' to parameter: 1"
TRACE: org.hibernate.type.BigDecimalType - "binding '27.2' to parameter: 2"
TRACE: org.hibernate.type.StringType - "binding 'Article_1' to parameter: 3"

This last version is what Hibernate will log for us for a given SQL statement, while the first version is what log4jdbc will log for that same statement. Log4jdbc is an open source library that logs all JDBC calls for a given application. What does the log4jdbc log provide that the Hibernate log does not?

•    Log4Jdbc logs all SQL statements, whereas Hibernate only logs the SQL statements it generates. If we call SQL directly in some place, we might miss some SQL being executed if we rely on Hibernate logs to tell us the whole truth.
•    Log4jdbc logs the time spent by every statement, 15 milliseconds in our example. That is great!
•    Log4jdbc logs the SQL and writes the parameter values right there for prepared statements, whereas Hibernate logs them in separated lines, and is much more verbose.
•    Log4jdbc can log the function in our code that caused the statement to be executed, in our case the persistAll method.
This deserves to be repeated: log4jdbc can log the line in our code, instead of the one deep down in Hibernate. It provides the name of the function, the file and the line number!
Of course, you need to compile your code enabling line number and file name information generation for your classes.
•    Log4jdbc generates a logical connection number that identifies the connection that was used to execute a statement (or JDBC API call). That can be great to debug threading or pooling problems, because it helps us to know what statements belong together and what connection is really being used to execute a given statement.

That is the “1” that appears in the first log, just before “/* insert…”.

And, even if it does show not in our example, log4jdbc allows us to log slow statements as warning or errors: we can set how many milliseconds make us consider a statement slow (and generate a warning log) or very slow (and generate an error log).

However, Hibernate logging has a definite advantage: it logs human readable SQL. For complex queries, which tend to be the interesting ones, this is a definite plus.

Please, note that because Hibernate generates comments at the SQL level, log4jdbc can see and log them as well. Therefore, do not forget to set the hibernate.use_sql_comments Hibernate property to true.

Basic log4jdbc configuration

Now, how do we get all those benefits? Here are the steps I undertook to add logt4jdbc 1.1 to my existing project:

1.    Add the required jars:

1.1.    The log4jdbc jar itself. It is log4jdbc3-1.1.jar for version 1.1 and JDBC 3, because I’m using a JDBC3 capable driver.
1.2.    The jars for libraries used by log4jdbc, in this version the Simple Logging Façade for Java, SLFJ4, version 1.5: this means slf4j-api-1.5.0.jar and sl4j-log4j12-1.5.0.jar, because we use log4j for logging, and this is the bridge between SLFJ4 and log4j 1.2. If you use a different logging tool, you’ll need to use a different jar.

2.    Modify the Hibernate configuration so that it uses log4jdbc interceptor. I did that by modifying as follows:

2.1.    Set hibernate.connection.driver_class to net.sf.log4jdbc.DriverSpy.
2.2.    Modify hibernate.connection.url, prepending jdbc:log4 to the existing connection url.
In my case, my old url was jdbc:hsqldb:hsql://localhost:9200/demo1_db. Therefore, the new url was jdbc:log4jdbc:hsqldb:hsql://localhost:9200/demo1_db.

3.    Modify so that we get the desired logging information from log4jdbc:

3.1.    Deactivate Hibernate SQL logging: comment the and entries.
But leave the hibernate.use_sql_comments Hibernate property set to true please: log4jdbc will log those comments too, and that will be nice.
3.2.    Configure log4jdbc logging: just set the  log4j.logger.jdbc.sqltiming category to ALL.
There are other logging categories, but that’s what I used to get the prior log, and most likely all you will need.

4.    Help log4jdbc in determining the line in our source code that caused the SQL statement to be executed.
To do this, log4jdbc traverses the call stack when an statement is executed, looking for the first function that belong to one of our classes. It will know that because we will tell it what is the root package for our classes. In my case, this is com.softwarementors. I just set the  system property to com.softwarementors passing it as a parameter to the JVM when executing my program, as follows:


That’s it: we are done!

Other goodies in the jdbc.sqltiming logger

We mentioned that log4jdbc allows us to mark a SQL statement as slow or very slow, logging it at the warn or error level, respectively. How do we do that? Well, if we consider a statements that takes 1000 milliseconds or more to deserve being logged as an error, and another one that takes 200 or more to deserve being logged as a warning, we will have to set two system properties, log4jdbc.sqltiming.warn.threshold=200 and log4jdbc.sqltiming.error.threshold=1000 The easiest way to do this is passing the following command line to the Java Virtual Machine, using the –D option, as follows:

-Dlog4jdbc.sqltiming.warn.threshold=200 -Dlog4jdbc.sqltiming.error.threshold=1000

I think you should almost always use this capability!

Understanding what “the line that caused the statement to be executed” means

Getting the line in my code that caused the SQL statement to be executed is really cool. However, some discussion is needed to understand what “the line that caused the SQL statement to be executed” means! As you probably know, Hibernate can delay the execution of SQL in order to get better performance. That means that the logical line that caused an SQL DELETE to be executed can be this one

entityManager.remove( myObject);

whereas the physical line that caused the DELETE statement to be executed might be this,


That happens because Hibernate might have delayed the statement execution until commit time. What log4jdbc logs is the physical line.

Configuring Hibernate and getting human readable SQL

As I said before, Hibernate has the edge when it comes to statement readability. Therefore, you might want to activate Hibernate logging just to get a nicely formatted SQL, while at the same time logging the information provided by log4jdbc. To do that, set the hibernate.format_sql Hibernate property to true in the file (or wherever you happen to specify those Hibernate properties). Then set enable the hibernate.SQL logger level to ALL. Of course, you will get duplicated logs for every SQL statement, but that will be easy to handle, because they will be consecutive and therefore easy to spot. And, if you use a tool like Chainsaw for viewing the logs, you can filter out the Hibernate logs and look at them only when you want to dig into the SQL itself!

More log4jdbc logging

As always, your logs are good only if you know and understand the existing logging categories provided by the library you want to monitor. There are four logging categories in log4jdbc. But just let me tell you that using jdbc.sqltiming will be enough if all you want to know is about the SQL statements that are executed. These are the logging categories provided by log4jdbc:

•    jdbc.sqlonly: logs every SQL statement the program executes, but just the SQL itself. It shows the parameter values when using prepared statements.

•    jdbc.sqltiming: as far as I know, it is exactly like jdbc.sqlonly, but adding the time the statement took to execute. I usually use this, instead of jdbc.sqlonly, and you should never use both at the same time unless you love to get almost duplicated logs.

•    jdbc.audit: logs all JDBC API calls, except those for the ResultSet interface. This can generate a lot of information, use it with care.

•    jdbc.resultset: this logs the ResultSet API calls only, so it does not overlap with jdbc.audit. This can generate massive amounts of information (lots of calls per returned row!), and I think you will rarely use this. Just to illustrate what kind of logging you can get out of jdbc.sqltiming, jdbc.audit and jdbc.resultset when combined, let’s see the log generated when the following line of code is executed:

InvoiceLine line = entityManager.find( InvoiceLine.class, lineId );

Well, here is the generated log:

DEBUG: jdbc.audit - "1. Connection.prepareStatement(/* load com.softwarementors.demo1.InvoiceLine */ select as id3_0_, invoicelin0_.version as version3_0_, invoicelin0_.article_id as article5_3_0_, invoicelin0_.pricePerUnit as pricePer3_3_0_, invoicelin0_.quantity as quantity3_0_ from InvoiceLine invoicelin0_ where returned net.sf.log4jdbc.PreparedStatementSpy@1b18235  com.softwarementors.demo1.Main.main("

DEBUG: jdbc.audit - "1. PreparedStatement.setLong(1, 3) returned   com.softwarementors.demo1.Main.main("

DEBUG: jdbc.sqltiming - " com.softwarementors.demo1.Main.main(
1. /* load com.softwarementors.demo1.InvoiceLine */ select
as id3_0_, invoicelin0_.version as version3_0_, invoicelin0_.article_id as article5_3_0_, invoicelin0_.pricePerUnit
as pricePer3_3_0_, invoicelin0_.quantity as quantity3_0_ from InvoiceLine invoicelin0_ where  {executed in 0 msec}"

DEBUG: jdbc.audit - "1. PreparedStatement.executeQuery() returned net.sf.log4jdbc.ResultSetSpy@46a09b  com.softwarementors.demo1.Main.main("
DEBUG: jdbc.resultset - "1. returned true  com.softwarementors.demo1.Main.main("
DEBUG: jdbc.resultset - "1. ResultSet.getInt(version3_0_) returned 0  com.softwarementors.demo1.Main.main("
DEBUG: jdbc.resultset - "1. ResultSet.wasNull() returned false  com.softwarementors.demo1.Main.main("
DEBUG: jdbc.resultset - "1. ResultSet.getLong(article5_3_0_) returned 1  com.softwarementors.demo1.Main.main("
DEBUG: jdbc.resultset - "1. ResultSet.wasNull() returned false  com.softwarementors.demo1.Main.main("
DEBUG: jdbc.resultset - "1. ResultSet.getBigDecimal(pricePer3_3_0_) returned 27.2  com.softwarementors.demo1.Main.main("
DEBUG: jdbc.resultset - "1. ResultSet.wasNull() returned false  com.softwarementors.demo1.Main.main("
DEBUG: jdbc.resultset - "1. ResultSet.getInt(quantity3_0_) returned 4  com.softwarementors.demo1.Main.main("
DEBUG: jdbc.resultset - "1. ResultSet.wasNull() returned false  com.softwarementors.demo1.Main.main("
DEBUG: jdbc.resultset - "1. returned false  com.softwarementors.demo1.Main.main("
DEBUG: jdbc.resultset - "1. ResultSet.close() returned   com.softwarementors.demo1.Main.main("

DEBUG: jdbc.audit - "1. PreparedStatement.getMaxRows() returned 0  com.softwarementors.demo1.Main.main("
DEBUG: jdbc.audit - "1. PreparedStatement.getQueryTimeout() returned 0  com.softwarementors.demo1.Main.main("
DEBUG: jdbc.audit - "1. PreparedStatement.close() returned   com.softwarementors.demo1.Main.main("
DEBUG: jdbc.audit - "1. Connection.isClosed() returned false  com.softwarementors.demo1.Main.main("
DEBUG: jdbc.audit - "1. Connection.getAutoCommit() returned false  com.softwarementors.demo1.Main.main("

As you can see, jdbc.audit adds tons of data, and jdbc.resultset adds even more. Just imagine the log had we executed a query returning 100 objects! It is very likely that you will want to enable this kind of logging for very little sections of code, programmatically, to avoid drowning in data. All these loggers provide different information depending on the level to which they are set:

•    DEBUG: logs the method, file and line number at which the JDBC API method was called (if possible). Of course, log the SQL or other applicable information, such as “Connection.isClosed() returned false”.

•    INFO: like DEBUG, omitting the method file and line number.

•    ERROR: log data about SQL exceptions only. If you want no log for a given logger, set its level to FATAL. As an example, if a logger logs this when its level is set to DEBUG,

DEBUG: jdbc.audit - "1. Connection.getAutoCommit() returned false  com.softwarementors.demo1.Main.main("

it will log this when it is set to INFO:

DEBUG: jdbc.audit - "1. Connection.getAutoCommit() returned false"

This can be much more manageable sometimes. By all means, if you are stepping through code with the debugger, set your logging level to INFO. You already know in which line you are (!), and you just want to focus in what JDBC methods are called at that moment: you don’t want to get that information in the middle of a lot of useless text. Finally, to log information about log4jdbc itself, you can use the log4jdbc.debug logging category. I always set it to ALL, because I find the information provided to be rather small and manageable (I’m talking about version 1.1 of log4jdbc all the time, so your mileage might vary). This is all logging I get in my sample application:

DEBUG: log4jdbc.debug - "... log4jdbc initializing ..."
DEBUG: log4jdbc.debug - "  log4jdbc.debug.stack.prefix = com.softwarementors"
DEBUG: log4jdbc.debug - "  log4jdbc.sqltiming.warn.threshold = 100"
DEBUG: log4jdbc.debug - "  log4jdbc.sqltiming.error.threshold = 500"
DEBUG: log4jdbc.debug - "x log4jdbc.drivers is not defined"
DEBUG: log4jdbc.debug - "  FOUND DRIVER org.hsqldb.jdbcDriver"
DEBUG: log4jdbc.debug - "... log4jdbc initialized! ..."

But it does not work with my JDBC driver!

Log4jdbc automatically recognizes and loads the more popular JDBC drivers, such as those for Oracle, HSQL, MySQL, the JTDS drivers for SQLServer and Sybase, etc. However, if your database driver is not directly recognized by log4jdbc, you still can integrate it with log4jdbc setting the following system property,


Again, the easiest way might be to pass it to the JVM using the –D option, as follows:


We want more!

Now, to the “wouldn’t it be nice?” department… I think it might be nice to be able to control logging per JDBC interface/class, i.e., Connection or PreparedStatement. An additional level of finer grained loggers might be nice too: I can imagine wanting to get logs for transaction related operations, but not the other Connection function calls. As always, the sky is the limit, but log4jdbc is a great library that you can put to good use with a minimal effort. As always, you should check newer log4jdbc versions for additional functionality.


I would like to thank José María Martínez for his criticism of this article.

Hibernate SQL Logging / Haciendo log de SQL con Hibernate

Here is the link to a (rather short ) article about SQL logging in Hibernate, Hibernate: logging SQL.

Escribir Código Correcto en Java

En mi último post abordé la problemática de la escritura de código robusto en presencia de errores, redirigiéndoos a un artículo sobre código exception-safe.

Hoy quiero hablar de código correcto, tema sobre el que también he escrito este artículo.

Antes de comenzar a hablar de corrección vale la pena recordar la siguiente frase de Bertrand Meyer,

“La corrección del Software es una noción relativa”

Y ello es así porque

Un sistema o elemento de software no es correcto o incorrecto por sí mismo; es correcto o incorrecto con respecto a una cierta especificación. Hablando estrictamente, no deberíamos discutir si ciertos elementos de software son correctos, sino si son consistentes con su especificación.

Esto se corresponde con mi experiencia real, y es que en la práctica el principal motivo por el que el software no es correcto es simplemente que no se define con claridad qué debe hacer.

Dicho de otro modo, no se establece un contrato.

Debo insistir en que utilicemos la palabra contrato en adelante. 

Porque, contrato suena a cosa seria. Y es que escribir código correcto requiere una cierta actitud.

En un contrato uno debería plasmar no sólo qué se debe hacer, sino qué precondiciones se deben cumplir para poder hacerlo (lo siento, no puedo llegar al pueblo de al lado con mi coche si me lo dejas sin gasolina, o al menos no tan fácilmente), y qué se garantiza (quizá llegar con mi coche con las cuatro ruedas pinchadas sea llegar, pero quizá no sea suficiente).

En el artículo se aborda la cuestión de cómo verificar los contratos de nuestro código Java mediante el uso de aserciones, una característica que está presente en Java desde la versión 1.4 del JDK.

Pero también se abordan cuestiones tales como cuán exigentes debemos ser en nuestro contrato, cómo asegurarnos de que no exigimos más de lo razonable (no hay nada más estúpido y a la vez frustrante que exigir algo que no se puede hacer), etc.

Vale la pena resaltar que el artículo pone el énfasis en técnicas concretas de programación, sin las que, desde mi punto de vista, la corrección del código no es más que una ficción.