Log SQL Statements With Parameter Values Filled In (Spring JDBC)

If you’re using parameterized queries with Spring JDBC (and why wouldn’t you?), it’s easy to log them with a simple log.debug() statement. But your logged statements will be full of ?’s instead of the values, which makes them much less useful. Suppose you’d like to know what was substituted for those question marks. It’s not so difficult if you use AspectJ.  Here is what is needed:

1. aspectjrt.jar and aspectjweaver.jar from here.
2. An aspect with a pointcut on the JdbcOperations interface, which JdbcTemplate implements.
3. @Before advice that intercepts the execution of JdbcTemplate methods and logs de-parameterized SQL statements.
4. Configuration of Spring applicationContext.xml to get it working.

Let’s start off with our class:

@Aspect
public class SqlLogger {
    private static final Logger log = LoggerFactory.getLogger(SqlLogger.class);

Here, I’m using an org.slf4j.Logger, but any logging framework will work.

Next step is to add the method that will capture the SQL and parameters as they are executed. Again, I’m using Spring JDBC, so all calls are made to an object that implements JdbcOperations.  We can set up our class to spy on all relevant calls by defining our method like so:

    @Before("execution(* org.springframework.jdbc.core.JdbcOperations.*(String, ..))")
    public void log(JoinPoint jp) throws Throwable {
    }

In methods of the JdbcOperations interface that begin with a String argument, the String is the SQL statement (with the question marks). Any values for parameters will appear as a subsequent argument in the form of an Object array. Let’s write the body of our method to identify what we’re looking for, fill in the parameters, and log the resulting SQL statement.

    @Before("execution(* org.springframework.jdbc.core.JdbcOperations.*(String, ..))")
    public void log(JoinPoint jp) throws Throwable {
        Object[] methodArgs = jp.getArgs(),
                 sqlArgs = null;

        // get the SQL statement
        String statement = methodArgs[0].toString();

        // find the SQL arguments (parameters)
        for (int i = 1, n = methodArgs.length; i < n; i++) {
            Object arg = methodArgs[i];
            if (arg instanceof Object[]) {
                sqlArgs = (Object[])arg;
                break;
            }
        }

        // fill in any SQL parameter place-holders (?'s)
        String completedStatement = (sqlArgs == null ? statement : fillParameters(statement, sqlArgs));

        // log it
        log.debug(completedStatement);
    }

Of course, the magic happens in the fillParameters method. That’s where the question marks in our parametized SQL statement are replaced with the actual values.

    private String fillParameters(String statement, Object[] sqlArgs) {
        // initialize a StringBuilder with a guesstimated final length
        StringBuilder completedSqlBuilder = new StringBuilder(Math.round(statement.length() * 1.2f));
        int index, // will hold the index of the next ?
            prevIndex = 0; // will hold the index of the previous ? + 1

        // loop through each SQL argument
        for (Object arg : sqlArgs) {
            index = statement.indexOf("?", prevIndex);
            if (index == -1)
                break; // bail out if there's a mismatch in # of args vs. ?'s

            // append the chunk of SQL coming before this ?
            completedSqlBuilder.append(statement.substring(prevIndex, index));
            // append the replacement for the ?
            if (arg == null)
                completedSqlBuilder.append("NULL");
            else
                completedSqlBuilder.append(arg.toString());

            prevIndex = index + 1;
        }

        // add the rest of the SQL if any
        if (prevIndex != statement.length())
            completedSqlBuilder.append(statement.substring(prevIndex));

        return completedSqlBuilder.toString();
    }

This is not a bad start to constructing a SQL statement with the parameters filled in. However it only tests for NULL or plugs in the argument’s toString() return value. If the argument is a String, it won’t be escaped. If it’s a Date, it won’t likely be in the proper format. We need to account for some of these possible scenarios, so let’s enhance our method:

    private static final DateTimeFormatter  DATE_FORMATTER = DateTimeFormat.forPattern("yyyy-MM-dd");;
    private static final DateTimeFormatter  TIMESTAMP_FORMATTER  = DateTimeFormat.forPattern("yyyy-MM-dd HH:mm:ss");

    ...

    private String fillParameters(String statement, Object[] sqlArgs) {
        // initialize a StringBuilder with a guesstimated final length
        StringBuilder completedSqlBuilder = new StringBuilder(Math.round(statement.length() * 1.2f));
        int index, // will hold the index of the next ?
            prevIndex = 0; // will hold the index of the previous ? + 1

        // loop through each SQL argument
        for (Object arg : sqlArgs) {
            index = statement.indexOf("?", prevIndex);
            if (index == -1)
                break; // bail out if there's a mismatch in # of args vs. ?'s

            // append the chunk of SQL coming before this ?
            completedSqlBuilder.append(statement.substring(prevIndex, index));
            if (arg == null)
                completedSqlBuilder.append("NULL");
            else if (arg instanceof String) {
                // wrap the String in quotes and escape any quotes within
                completedSqlBuilder.append('\'')
                   .append(arg.toString().replace("'", "''"))
                    .append('\'');
            }
            else if (arg instanceof Date) {
                // convert it to a Joda DateTime
                DateTime dateTime = new DateTime((Date)arg);
                // test to see if it's a DATE or a TIMESTAMP
                if (dateTime.getHourOfDay() == LocalTime.MIDNIGHT.getHourOfDay() &&
                    dateTime.getMinuteOfHour() == LocalTime.MIDNIGHT.getMinuteOfHour() &&
                    dateTime.getSecondOfMinute() == LocalTime.MIDNIGHT.getSecondOfMinute()) {
                    completedSqlBuilder.append("DATE '")
                        .append(DATE_FORMATTER.print(dateTime))
                        .append('\'');
                }
                else {
                    completedSqlBuilder.append("TIMESTAMP '")
                        .append(TIMESTAMP_FORMATTER.print(dateTime))
                        .append('\'');
                }
            }
            else
                completedSqlBuilder.append(arg.toString());

            prevIndex = index + 1;
        }

        // add the rest of the SQL if any
        if (prevIndex != statement.length())
            completedSqlBuilder.append(statement.substring(prevIndex));

        return completedSqlBuilder.toString();
    }

Above, you can see I added support for Strings and Dates. This method should now cover most of the common SQL parameter types. Note that I’m using a few classes from Joda Time: DateTimeFormatter, DateTimeFormat, DateTime and LocalTime. You could eliminate the dependency on Joda by using Java’s Calendar and SimpleDateFormat classes instead, but either way you must use something that lets you test whether the java Date object represents a SQL DATE or a TIMESTAMP (whether it has time information or not) and format it.

Please also note–and this is important–the method is outputting DATEs and TIMESTAMPs in a syntax compatible with a PostgreSQL database, e.g. “DATE ‘2009-05-11′”. This may not be appropriate for a different RDBMS.

Now complete, this class will log SQL statements with the parameter values filled in, so that instead of:

SELECT   product_id, name, price, quantity
FROM     product
WHERE    product_code IN (?, ?, ?)
         AND added_on > ?
         AND price < ?

Your logs will show:

SELECT   product_id, name, price, quantity
FROM     product
WHERE    product_code IN ('GX110S', 'P134Q', 'G11ZX')
         AND added_on > DATE '2013-04-26'
         AND price < 200

There is just one more step to get this working. Add to your Spring applicationContext.xml:

<!-- enable AspectJ support -->
<aop:aspectj-autoproxy/>

<!-- declare the SQL logger class as a bean -->
<bean id="sqlLogger" class="my.package.SqlLogger" />

<!-- JdbcTemplate must be a Spring-managed bean -->
<bean id="jdbcTemplate" class="org.springframework.jdbc.core.JdbcTemplate" p:dataSource-ref="jdbcDataSource" />

<!-- wire the JdbcTemplate into your DAO (Alternatively, you could use autowiring) -->
<bean id="myDao" class="my.dao.ExampleDao" p:jdbcTempate-ref="jdbcTemplate" />

And that’s it!

Here is the full java class file for our logger:

@Aspect
public class SqlLogger {
    private static final Logger log = LoggerFactory.getLogger(SqlLogger.class);
    private static final DateTimeFormatter  DATE_FORMATTER = DateTimeFormat.forPattern("yyyy-MM-dd");;
    private static final DateTimeFormatter  TIMESTAMP_FORMATTER  = DateTimeFormat.forPattern("yyyy-MM-dd HH:mm:ss");

    @Before("execution(* org.springframework.jdbc.core.JdbcOperations.*(String, ..))")
    public void log(JoinPoint jp) throws Throwable {
        Object[] methodArgs = jp.getArgs(),
                 sqlArgs = null;

        // get the SQL statement
        String statement = methodArgs[0].toString();

        // find the SQL arguments (parameters)
        for (int i = 1, n = methodArgs.length; i < n; i++) {
            Object arg = methodArgs[i];
            if (arg instanceof Object[]) {
                sqlArgs = (Object[])arg;
                break;
            }
        }

        // fill in any SQL parameter place-holders (?'s)
        String completedStatement = (sqlArgs == null ? statement : fillParameters(statement, sqlArgs));

        // log it
        log.debug(completedStatement);
    }

    private String fillParameters(String statement, Object[] sqlArgs) {
        // initialize a StringBuilder with a guesstimated final length
        StringBuilder completedSqlBuilder = new StringBuilder(Math.round(statement.length() * 1.2f));
        int index, // will hold the index of the next ?
            prevIndex = 0; // will hold the index of the previous ? + 1

        // loop through each SQL argument
        for (Object arg : sqlArgs) {
            index = statement.indexOf("?", prevIndex);
            if (index == -1)
                break; // bail out if there's a mismatch in # of args vs. ?'s

            // append the chunk of SQL coming before this ?
            completedSqlBuilder.append(statement.substring(prevIndex, index));
            if (arg == null)
                completedSqlBuilder.append("NULL");
            else if (arg instanceof String) {
                // wrap the String in quotes and escape any quotes within
                completedSqlBuilder.append('\'')
                   .append(arg.toString().replace("'", "''"))
                    .append('\'');
            }
            else if (arg instanceof Date) {
                // convert it to a Joda DateTime
                DateTime dateTime = new DateTime((Date)arg);
                // test to see if it's a DATE or a TIMESTAMP
                if (dateTime.getHourOfDay() == LocalTime.MIDNIGHT.getHourOfDay() &&
                    dateTime.getMinuteOfHour() == LocalTime.MIDNIGHT.getMinuteOfHour() &&
                    dateTime.getSecondOfMinute() == LocalTime.MIDNIGHT.getSecondOfMinute()) {
                    completedSqlBuilder.append("DATE '")
                        .append(DATE_FORMATTER.print(dateTime))
                        .append('\'');
                }
                else {
                    completedSqlBuilder.append("TIMESTAMP '")
                        .append(TIMESTAMP_FORMATTER.print(dateTime))
                        .append('\'');
                }
            }
            else
                completedSqlBuilder.append(arg.toString());

            prevIndex = index + 1;
        }

        // add the rest of the SQL if any
        if (prevIndex != statement.length())
            completedSqlBuilder.append(statement.substring(prevIndex));

        return completedSqlBuilder.toString();
    }
}

Consider now that you might want to log the execution time of each SQL statement. Rather than using the @Before annotation, you would use @Around, and time the execution similar to how I did it in my SQL statement profiler. This gives you even more useful information. Keep in mind that there is a performance impact on your application when logging all SQL statements. You likely would not want to have your SQL logger enabled in a production environment.

So to review: we’ve created an Aspect to log SQL statements in Java unobtrusively, with their parameter values filled in, and we wired up our logger in the Spring config to intercept calls to JdbcTemplate. We also considered timing the execution of the logged SQL statements.