Archivo de la categoría: Articles

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;
    else
      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:

@CheckForNull
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:

@NonNull
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:

@NonNull
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 http://code.google.com/p/google-collections/issues/detail?id=247, or http://osdir.com/ml/java.findbugs.general/2006-09/msg00063.html, 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:

@edu.umd.cs.findbugs.annotations.DefaultAnnotation(value=NonNull.class)
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 http://www.disi.unige.it/person/AnconaD/FTfJP06/paper03.pdf

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:

file.delete();
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:

@edu.umd.cs.findbugs.annotations.CleanupObligation
public static class ResourceClass {
  @edu.umd.cs.findbugs.annotations.CreatesObligation()
  public ResourceClass() {
    // Do nothing: just for illustrative purposes
  }

  @edu.umd.cs.findbugs.annotations.DischargesObligation
  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
    resource.toString();
  }
  finally {
    resource.doCleanup();
  }
}

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.

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( DataAccess.java:40)
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 hibernate.properties 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 log4j.properties so that we get the desired logging information from log4jdbc:

3.1.    Deactivate Hibernate SQL logging: comment the log4j.logger.org.hibernate.SQL=ALL and log4j.logger.org.hibernate.type=ALL 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:

-Dlog4jdbc.debug.stack.prefix=com.softwarementors.

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,

entitManager.getTransaction().commit();

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 hibernate.properties 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 invoicelin0_.id 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 invoicelin0_.id=?) returned net.sf.log4jdbc.PreparedStatementSpy@1b18235  com.softwarementors.demo1.Main.main(Main.java:159)"

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

DEBUG: jdbc.sqltiming - " com.softwarementors.demo1.Main.main(Main.java:159)
1. /* load com.softwarementors.demo1.InvoiceLine */ select invoicelin0_.id
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
invoicelin0_.id=3  {executed in 0 msec}"

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

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

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(Main.java:159)"

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,

log4jdbc.drivers=<driver>[,<driver>,...]

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

-Dlog4jdbc.drivers=<driver>[,<driver>,...]

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.

Acknowledgements

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.

High Quality Java Code: Contracts & Assertions

Here is the link to High Quality Java Code: Contracts & Assertions!