java.sql.SQLNonTransientException: [Amazon][JDBC](10900) Not all parameters have been populated

Question

I am building a Spring Boot application that is multithreaded utilizing the Spring @EnableAsync and @Async annotations. When I run the application with a single thread (CorePoolSize 1, MaxPoolSize 1) everything works as expected. When I increase the pool size above 1 on what seems to be random occurrences I get the java.sql.SQLNonTransientException: [Amazon]JDBC Not all parameters have been populated. error when making calls to an Amazon AWS Redshift database.

In the ServiceProcessBean.java I have auto wired my ProcessService class (the threaded work to be done) and the ShipmentDAO which loads a list of shipment IDs to be processed by the ProcessService.process() method, code below.

@Component
public class ShipmentBatchBean {

  private Logger logger = LoggerFactory.getLogger(this.getClass());

  @Autowired
  private ShipmentDAO shipmentDAO;

  @Autowired
  private ProcessService processService;

  @Scheduled(
    initialDelayString = "${executor.delay.initial}",
    fixedDelayString = "${executor.delay.fixed}"
  )
  public void cronJob() throws InterruptedException, ExecutionException {

    List<CompletableFuture<Boolean>> asyncResponse = new ArrayList<>();

    logger.info("Starting cronJob() method");

    try {
      List<String> shipments = shipmentDAO.getAllShipmentsReadyForIeta();
      logger.info("There are {} shipments to be processed in the data store", 
          shipments.size());

      for(String shipment : shipments) {
        asyncResponse.add(processService.process(shipment));
      }
    } catch (Exception ex) {
      logger.error(ex.getMessage());
      ex.printStackTrace();
    }

    CompletableFuture.allOf(asyncResponse.toArray(
      new CompletableFuture[asyncResponse.size()]
    )).join();

    logger.info("Ending cronJob() method");
  }

}

Finally, in the ProcessService we auto wire several repositories and a JSON service and begin the process() method with the @Async annotation. See code snipplet below.

@Service
public class ProcessServiceBean implements ProcessService {

    private Logger logger = LoggerFactory.getLogger(getClass());

    @Autowired
    private ShipmentDAO shipmentDAO;

    @Autowired
    private OssItemDAO ossItemDAO;

    @Autowired
    private OssHeaderDAO ossHeaderDAO;

    @Autowired
    private OssDataJsonServiceBean ossDataJsonServiceBean;

    @Override
    @Async
    public CompletableFuture<Boolean> process(String shipmentId) {

      Shipment shipment = null;

      logger.debug("Retrieving from ieta_input (shipment id {})",
        shipmentId);
      try {
        shipment = shipmentDAO.getOneBy(shipmentId);
      } catch (SQLException e) {
        logger.error("process of shipment {}) ended in error",
          shipmentId,
      };
      return CompletableFuture.completedFuture(false);
    }

 code snipped for brevity.

Finally in the ShipmentDAO we have the getOneBy() method that returns the shipment record requested.

@Override
public Shipment getOneBy(String shipmentId) throws SQLException {
    Shipment shipment = null;
    Connection conn = null;

    String sql = "SELECT * FROM myschema.tablename WHERE shipmentid = ? LIMIT 1";

    try {
      conn = dataSource.getConnection();
      PreparedStatement ps = conn.prepareStatement(sql);
      ps.setString(1, shipmentId);
      ResultSet rs = ps.executeQuery();
      if(rs.next()) {
        shipment = new Shipment(
            rs.getLong("rowid"),
            rs.getString("shipmentid"),
            ...
            rs.getString("more_info_here")
        );
      }
      ps.close();
    } catch(SQLException e) {
      logger.error("ShipmentDAO.getOneBy() failed: {}",
        e.getMessage());
      e.printStackTrace();
      throw e;
    } finally {
      if(conn != null) {
      try {
        conn.close();
      } catch (SQLException se) { }
    }
  }
  return shipment;
}

I have reached out to AWS and they only have two instances in their knowledge base where this error has been reported with only "user code issue" being the resolution.

I don't see any clear thread safety issues but it is acting like it because the code works flawlessly when only one thread is fired off and each shipment is processed in series.

Does anyone see a glaring problem or need more information? Any help appreciated.

Stacktrace follows:

2018-Oct-22 15:57:30.960 ERROR- [shipment-executor-8] [Amazon][JDBC](10900) Not all parameters have been populated.
org.springframework.dao.InvalidDataAccessResourceUsageException: could not extract ResultSet; SQL [n/a]; nested exception is org.hibernate.exception.SQLGrammarException: could not extract ResultSet
at org.springframework.orm.jpa.vendor.HibernateJpaDialect.convertHibernateAccessException(HibernateJpaDialect.java:261)
at org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:244)
at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.translateExceptionIfPossible(AbstractEntityManagerFactoryBean.java:503)
at org.springframework.dao.support.ChainedPersistenceExceptionTranslator.translateExceptionIfPossible(ChainedPersistenceExceptionTranslator.java:59)
at org.springframework.dao.support.DataAccessUtils.translateIfNecessary(DataAccessUtils.java:209)
at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:147)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:133)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.data.repository.core.support.SurroundingTransactionDetectorMethodInterceptor.invoke(SurroundingTransactionDetectorMethodInterceptor.java:57)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)
at com.sun.proxy.$Proxy91.getFirstByFactDeliveryNumberIsOrSapDeliveryNumberIs(Unknown Source)
at com.accenture.service.ProcessServiceBean.process(ProcessServiceBean.java:91)
at com.accenture.service.ProcessServiceBean$$FastClassBySpringCGLIB$$45e1a1ec.invoke(<generated>)
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:738)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:282)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.interceptor.AsyncExecutionInterceptor$1.call(AsyncExecutionInterceptor.java:115)
at org.springframework.aop.interceptor.AsyncExecutionAspectSupport$CompletableFutureDelegate$1.get(AsyncExecutionAspectSupport.java:328)
at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1590)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Caused by: org.hibernate.exception.SQLGrammarException: could not extract ResultSet
at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:106)
at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:109)
at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:95)
at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:79)
at org.hibernate.loader.Loader.getResultSet(Loader.java:2117)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1900)
at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1876)
at org.hibernate.loader.Loader.doQuery(Loader.java:919)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:336)
at org.hibernate.loader.Loader.doList(Loader.java:2617)
at org.hibernate.loader.Loader.doList(Loader.java:2600)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2429)
at org.hibernate.loader.Loader.list(Loader.java:2424)
at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:501)
at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:371)
at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:216)
at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1326)
at org.hibernate.internal.QueryImpl.list(QueryImpl.java:87)
at org.hibernate.jpa.internal.QueryImpl.list(QueryImpl.java:606)
at org.hibernate.jpa.internal.QueryImpl.getSingleResult(QueryImpl.java:529)
at org.hibernate.jpa.criteria.compile.CriteriaQueryTypeQueryAdapter.getSingleResult(CriteriaQueryTypeQueryAdapter.java:54)
at org.springframework.data.jpa.repository.query.JpaQueryExecution$SingleEntityExecution.doExecute(JpaQueryExecution.java:208)
at org.springframework.data.jpa.repository.query.JpaQueryExecution.execute(JpaQueryExecution.java:87)
at org.springframework.data.jpa.repository.query.AbstractJpaQuery.doExecute(AbstractJpaQuery.java:116)
at org.springframework.data.jpa.repository.query.AbstractJpaQuery.execute(AbstractJpaQuery.java:106)
at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.doInvoke(RepositoryFactorySupport.java:499)
at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.invoke(RepositoryFactorySupport.java:477)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.data.projection.DefaultMethodInvokingMethodInterceptor.invoke(DefaultMethodInvokingMethodInterceptor.java:56)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:282)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:136)
... 24 more
Caused by: java.sql.SQLNonTransientException: [Amazon][JDBC](10900) Not all parameters have been populated.
at com.amazon.exceptions.ExceptionConverter.toSQLException(Unknown Source)
at com.amazon.jdbc.common.SPreparedStatement.executeQuery(Unknown Source)
at sun.reflect.GeneratedMethodAccessor79.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.tomcat.jdbc.pool.StatementFacade$StatementProxy.invoke(StatementFacade.java:114)
at com.sun.proxy.$Proxy101.executeQuery(Unknown Source)
at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:70)
... 55 more

Cahier

FYI: You should be using try-with-resources. Would clean up your code a lot, and be less likely to leak resources. – Tread

Thanks for the reminder Andreas. Added. – Cahier

I am confused by the stacktrace saying that ProcessServiceBean.process() at line 91 calls a method named getFirstByFactDeliveryNumberIsOrSapDeliveryNumberIs() to some Hibernate object, when your source code only shows call to a getOneBy() method. – Tread

I pulled a stacktrace that was on another method (my apologies) but it is the exact same stack trace as the getOneBy() method trace, simply replace the getFirstByFactDeliveryNumberIsOrSapDeliveryNumberIs() with getOneBy(). – Cahier

On another method also called process on another class also called ProcessServiceBean? How about you show stacktrace and code that matches. – Tread

Answer 1

We finally have resolution! After an arduous set of testing it came down to the JDBC driver not being thread safe. We experienced this problem with numerous versions of the redshift-jdbc41 and redshift-jdbc42 drivers and finally settled in on one <version>1.2.10.1009</version> that no longer throws the errors and processes multiple threads concurrently. If you have a ticket open with Amazon Support you can refer them to Case ID 5466870321 where we provided all of the details necessary for them to acknowledge that the problem is in the driver itself.

As noted by code tachyon (thanks for your input), the problem does seem to be in the prepared statement functionality of the JDBC driver and as such we have not seen any data corruption in the database itself from these issues as they persist before the request is forwarded to Redshift.

On a final note, I am extremely surprised that there are a rather large number of JDBC driver versions released by Amazon and everything we have tested post 1.2.10.1009 contains this thread safety issue, yet Amazon didn't know about it and there is not a single stackoverflow or other Google search that reveals this as a problem with the exception of this post.

I hope this helps someone else who is finding their multi-threaded application is not working properly.

Cahier

I got exactly the same issue with 'com.amazon.redshift:redshift-jdbc42:1.2.16.1027'. Switching to '1.2.10.1009' fixed it. Thanks a lot! – Soares

I have the same problem with the redshift-jdbc42 version 1.2.18.1036. I got it solved by setting the size of the connection pool to 1, by which multi-threaded access to the database is avoided. Not nice! Really horrible from a performance point of view. – Shrovetide

Yes, I can confirm that version 1.2.10.1009 of the redshift-jdbc42-no-awssdk driver is thread-safe and works with concurrent requests and prepared statements. I was using 1.2.18.1036 which did not work. – Fete

Seems to be okay when upgrading to compile group: 'com.amazon.redshift', name: 'redshift-jdbc42-no-awssdk', version: '1.2.36.1060' – Alexandrina

1.2.41.1065 is still giving me the error. My workaround, for now, is to add synchronized to the method that prepares and executes the statement. – Maypole

Answer 2

Encountered a simillar issue , the cuplrit is prepared statement caching on the server side while using named params. The prepared statement and the named params are sent seperately and the redshift jdbc driver is not able to resolve the named params sent across multiple concurrent connections for the same query. A temporary fix is to replace the "?" in "String sql = "SELECT * FROM myschema.tablename WHERE shipmentid = ? LIMIT 1"; with the actual parameter. This ofcourse opens you upto sql injection attacks and you lose the benefit of a cached prepared statement with execution plan. However we decided to pursue the option until a permanent fix was available, YMMV.

Automata