org.springframework.jdbc.support.SQLErrorCodesFactory.getErrorCodes is blocking threads

Question

I'm running a tomcat server with services developed using spring v 4.1.0. I'm creating jdbc connections to an informix database and occasionally get an error. These connections are single connections and not pooled (as I'm connecting to dynamically generated database hosts depending upon varying input criteria).

Over time everything seems to be progressing fine and then all of a sudden I start getting a massive upswing of tomcat threads that continues until I hit my max threads and all requests to the server get rejected. Doing a thread dump shows that all the threads are hung on org.springframework.jdbc.support.SQLErrorCodesFactory.getErrorCodes.

- org.springframework.jdbc.support.SQLErrorCodesFactory.getErrorCodes(javax.sql.DataSource) @bci=56, line=204 (Interpreted frame)
- org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.setDataSource(javax.sql.DataSource) @bci=5, line=134 (Interpreted frame)
- org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.<init>(javax.sql.DataSource) @bci=6, line=97 (Interpreted frame)
- org.springframework.jdbc.support.JdbcAccessor.getExceptionTranslator() @bci=22, line=99 (Interpreted frame)
- org.springframework.jdbc.support.JdbcAccessor.afterPropertiesSet() @bci=25, line=138 (Interpreted frame)
- org.springframework.jdbc.core.JdbcTemplate.<init>(javax.sql.DataSource, boolean) @bci=50, line=182 (Interpreted frame)
- com.business.stores.data.dao.impl.BaseDAOImpl.getJdbcTemplate(int) @bci=86, line=53 (Interpreted frame)
...

I've pulled up the source for the spring class listed above and there is a syncronized block within it, but I'm not sure why it would be failing to execute and hanging up all the threads in the system. (It appears that after it gets blocked any subsequent SQL errors will also block until there are no threads left available on the box. Here is the code from Spring in question:

public SQLErrorCodes getErrorCodes(DataSource dataSource) {
    Assert.notNull(dataSource, "DataSource must not be null");
    if (logger.isDebugEnabled()) {
        logger.debug("Looking up default SQLErrorCodes for DataSource [" + dataSource + "]");
    }

    synchronized (this.dataSourceCache) {
        // Let's avoid looking up database product info if we can.
        SQLErrorCodes sec = this.dataSourceCache.get(dataSource);
        if (sec != null) {
            if (logger.isDebugEnabled()) {
                logger.debug("SQLErrorCodes found in cache for DataSource [" +
                        dataSource.getClass().getName() + '@' + Integer.toHexString(dataSource.hashCode()) + "]");
            }
            return sec;
        }
        // We could not find it - got to look it up.
        try {
            String dbName = (String) JdbcUtils.extractDatabaseMetaData(dataSource, "getDatabaseProductName");
            if (dbName != null) {
                if (logger.isDebugEnabled()) {
                    logger.debug("Database product name cached for DataSource [" +
                            dataSource.getClass().getName() + '@' + Integer.toHexString(dataSource.hashCode()) +
                            "]: name is '" + dbName + "'");
                }
                sec = getErrorCodes(dbName);
                this.dataSourceCache.put(dataSource, sec);
                return sec;
            }
        }
        catch (MetaDataAccessException ex) {
            logger.warn("Error while extracting database product name - falling back to empty error codes", ex);
        }
    }

    // Fallback is to return an empty SQLErrorCodes instance.
    return new SQLErrorCodes();
}

-------UPDATE At this point I'm at a loss to determine what is locking dataSourceCache or how to fix it.

Turned on logging (and debug) for the spring module and then forced the issue by calling the service with a site in a different environment (and therefore different password). The service returned the invalid password response as expected, but there was these lines in the log.

It appears to have loaded the data correctly:

2015-10-27 21:09:26,677||DEBUG||SQLErrorCodesFactory.getErrorCodes(175)||||SQL error codes for 'Informix Dynamic Server' found

But it had some sort of issue retrieving the data:

2015-10-27 21:09:33,162||DEBUG||SQLErrorCodesFactory.getErrorCodes(199)||||Looking up default SQLErrorCodes for DataSource [org.springframework.jdbc.datasource.SingleConnectionDataSource@149e2931]
2015-10-27 21:09:34,254||DEBUG||SQLErrorCodesFactory.getErrorCodes(217)||||Database product name cached for DataSource [org.springframework.jdbc.datasource.SingleConnectionDataSource@50e91794]: name is 'Informix Dynamic Server'

2015-10-27 21:09:34,255||INFO ||MarkdownVoidByCashierDAOImpl.getVoidByCashierFromStore(47)||||Created JDBC Template for 68

And then it threw the error that I expected:

2015-10-27 21:09:34,317||WARN ||SQLErrorCodesFactory.getErrorCodes(227)||||Error while extracting database product name - falling back to empty error codes
org.springframework.jdbc.support.MetaDataAccessException: Could not get Connection for extracting meta data; nested exception is org.springframework.jdbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is java.sql.SQLException: Incorrect password or user com.informix.asf.IfxASFRemoteException: user1@::ffff:10.63.112.131 is not known on the database server.
        at org.springframework.jdbc.support.JdbcUtils.extractDatabaseMetaData(JdbcUtils.java:297)
        at org.springframework.jdbc.support.JdbcUtils.extractDatabaseMetaData(JdbcUtils.java:324)
        at org.springframework.jdbc.support.SQLErrorCodesFactory.getErrorCodes(SQLErrorCodesFactory.java:214)
        at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.setDataSource(SQLErrorCodeSQLExceptionTranslator.java:134)
        at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.<init>(SQLErrorCodeSQLExceptionTranslator.java:97)
        at org.springframework.jdbc.support.JdbcAccessor.getExceptionTranslator(JdbcAccessor.java:99)
        at org.springframework.jdbc.support.JdbcAccessor.afterPropertiesSet(JdbcAccessor.java:138)
        at org.springframework.jdbc.core.JdbcTemplate.<init>(JdbcTemplate.java:182)
...

Of course, this doesn't appear to have recreated the issue either (I didn't really expect it to, previous attempts at recreating the issue have failed) so I will continue monitoring until the issue recurs.

------UPDATE 2

So the issue has recurred on the box. Looking at the logs with debugging I'm not seeing much to point me towards the root cause though.

I'm seeing this basic pattern over and over again:

2015-10-27 21:28:11,178||DEBUG||SQLErrorCodesFactory.getErrorCodes(199)||||Looking up default SQLErrorCodes for DataSource [org.springframework.jdbc.datasource.SingleConnectionDataSource@3da15c49]
...
2015-10-27 21:28:13,481||DEBUG||SQLErrorCodesFactory.getErrorCodes(217)||||Database product name cached for DataSource [org.springframework.jdbc.datasource.SingleConnectionDataSource@207e4667]: name is 'Informix Dynamic Server'
2015-10-27 21:28:13,482||DEBUG||SQLErrorCodesFactory.getErrorCodes(175)||||SQL error codes for 'Informix Dynamic Server' found

The hex value at the end of the single connection data source is the only thing that changes.

On an error or two I'm seeing the following:

2015-10-27 21:27:33,622||WARN ||SQLErrorCodesFactory.getErrorCodes(227)||||Error while extracting database product name - falling back to empty error codes

But I believe that only shows up when I give a completely invalid server name as the target. It does appear that it goes into the synchronized block on every SQL call though. A grep on the log for the lines containing "Looking for" vs "found" shows about a 300 difference where lookings haven't hit a corresponding found. This would be consistent with the threads blocking and being unable to advance since the looking debug line occurs outside of the syncronized block.

Answer 1

I had the same problem, but I found the solution. Because of the jdbc connection or the database connection has no timeout property and the default timeout is never timeout, so after the queue or pool is full, and this.dataSourceCache.get(dataSource); need another resource to process, so it will never timeout and no space to run this line, so it wait here forever.

The solution is set a timeout time for jdbc or what you use for database connection. Hope it will help.