Hibernate findById isn't finding records that it previously found

Question

We have a very simple method that uses "findById".

public Cart getCart(long cartId) {
 Cart cart = null;

 try {

  dbSession.beginTransaction();
  cart = (Cart)dbSession.findById(Cart.class, cartId);
  dbSession.commitTransaction();

  if (logger.isDebugEnabled()) {
   logger.debug("The getCart call committed successfully");
  }

 } finally {
  if (dbSession.needsRollback()) {
   dbSession.rollbackTransaction();
  }
 }

 logGetCartResults(cartId, cart);

 return cart;
}

private void logGetCartResults(long cartId, Cart cart) {
 if (logger.isDebugEnabled()) {

  StringBuffer message = new StringBuffer("Cart id ");
  message.append(cartId)
      .append(" was ");

  if (cart != null) {
   message.append("not ");
  }

  message.append("null");

  logger.debug(message.toString());
 }
}

This method sometimes gets called from another application in rapid succession (it's basically another system that loads up a cart). We have a thread that makes a cart, commits the record to the database, and then the application calls once for each item that needs to go into the database. Though the other application sends in sequence, and waits for a response, tomcat gets these on separate threads.

We're seeing initial calls to "getCart" actually able to find the record. Occasionally, a call fails, even after other calls have worked. Here's some of the log to provide more context:

    DEBUG 2009-06-18 16:10:57,145 [http-8080-Processor20] com.eroi.managers.impl.DefaultPurchaseManager: Looking for cartId 49
    DEBUG 2009-06-18 16:10:57,146 [http-8080-Processor20] com.eroi.persistors.impl.DefaultPurchasePersistor: The getCart call committed successfully
    DEBUG 2009-06-18 16:10:57,146 [http-8080-Processor20] com.eroi.persistors.impl.DefaultPurchasePersistor: Cart id 49 was not null
    ...
    DEBUG 2009-06-18 16:10:57,522 [http-8080-Processor14] com.eroi.managers.impl.DefaultPurchaseManager: Looking for cartId 49
    DEBUG 2009-06-18 16:10:57,523 [http-8080-Processor14] com.eroi.persistors.impl.DefaultPurchasePersistor: The getCart call committed successfully
    DEBUG 2009-06-18 16:10:57,523 [http-8080-Processor14] com.eroi.persistors.impl.DefaultPurchasePersistor: Cart id 49 was not null
    ...
    DEBUG 2009-06-18 16:10:57,934 [http-8080-Processor10] com.eroi.managers.impl.DefaultPurchaseManager: Looking for cartId 49    
    DEBUG 2009-06-18 16:10:57,934 [http-8080-Processor10] com.eroi.persistors.impl.DefaultPurchasePersistor: The getCart call committed successfully
    DEBUG 2009-06-18 16:10:57,934 [http-8080-Processor10] com.eroi.persistors.impl.DefaultPurchasePersistor: Cart id 49 was null

So. thread 20, 14 were successful, but thread 10 couldn't locate the record. What gives? We don't have any caching going on (other than the default 1st level caching).

<hibernate-configuration>
    <session-factory>
     <property name="current_session_context_class">thread</property>
     <property name="hibernate.connection.datasource">java:/comp/env/jdbc/ourdb</property>
     <property name="hibernate.dialect">org.hibernate.dialect.MySQLDialect</property>
    </session-factory>
</hibernate-configuration>

Any insight, ideas or . . . well, anything, is appreciated.

Answer 1

Is it possible that at the time thread 10 starts its transaction that the ID is not yet a fully committed transaction? So basically I'm asking - if you have a cart 49 already in the database (say at the start of the program) can the thread still have this problem?

Answer 2

This was due to a transaction bug in our code. Even though it looked like our code was starting a new Session in each request, we found that occassionally, these new Session's wouldn't get a new JDBC connection. We tracked down where we were not committing a transaction. Because of the way we manage calls to begin and commit, we were essentially creating long running transaction that never completed (and didn't behave as expected).