on child insert parent, child collection updated in DB but N

[dukehoops]

In abtract
I am load testing a Hibernate/JBC3 web application and am seeing that about 7% of the time inserting a child entity into a previously-empty collection results in update (INSERT) into DB but local cache remains unchanged:
-collection Node is still empty
-there is no child Entity node
This does not appear to be a race condition, as from that point on in any TX parent.getChildren() will return an empty collection from cache (even though DB state is non-empty).
This seems vaguely similar to https://jira.jboss.org/jira/browse/JBCACHE-1481 but that issue's marked resolved.


In detail

App Config
Single Tomcat 6 NIO
Hibernate 3.3.1.GA
JBossCache 3.0.3.GA - Local Cache only; using default Locking (MVCC); READ_COMMITTED isolation
BTM JTA transaction manager

Load Test
JMeter load test where each of userCount users loop over the following scenario of HTTP requests:

for(I iterations)
{
 login();
 thinkTime //sleep;
 getRestrictedData(); //requires being logged in
 thinkTime //sleep;
 logout();
 thinkTime //sleep;
}

App Pseudo Code

Domain Model

-Transactional entity caches User, UserSession; collection cache User.sessions

class User{
 private long id;
 private Set<UserSession> sessions; //1-to-[0,1] modeled as one-to-many with unique constraint

 public boolean isLoggedIn()
{
 return !getSessions().isEmpty();
}

public void addSession(UserSession us)
{
 us.setUser(this);
 sessions.add(us);
}

public Set<UserSessions> getSessions()
{
 return sessions;
}
}



class UserSession
{
 private User user;

 void setUser(User usr)
{
 this.user = usr;
}

}

Service Methods

//insert new UserSession if credentials check out
//throw exception otherwise
public void login(id, credentials)
{
 User usr = dao.getUser(id);
 if(credentials == bad)
 {
 throw new AuthenticationException();
 }
 usr.add(new UserSession());
}

//return data only if a userSession is present
//throw exception otherwise
public String getRestrictedData(id)
{
 User usr = dao.getUser(id);
 if(! usr.isLoggedIn())
 {
 throw new AuthorizationException("not logged in");
 }
 return data;
}

public void logout()
{
 //clear userSessions
}
}

Problem Observed

When userCount==1, no requests fail, regardless of thinkTime (varied latter between 0 and 2000ms)
When userCount is > 30, about 10-20% of users eventually (and most of the time on the very 1st iteration), fail like so:

-login() //success
-getRestrictedData() //fail: user not logged in

My load test terminates on 1st failure. Inspecting states of DB and JBoss Cache (via JMX) reveal:
-DB does have record of UserSession in question
-In Collection cache: User.sessions Node contains an empty PersistentSet
-In entity cache: User node references above (empty) collection; no node for UserSession that is in DB;
-hibernateVersion of User (parent) is updated in DB but not in Cache node

Musings

Though I am unable to repro this problem with 1 user, it is not possible for user A to affect state of user B in my app. So I am not quite clear on what's going on here. Since I don't (yet) understand the internals of MVCC (and jbc in general), I'd appreciate any thoughts and answers to the following questions that'll help me narrow down the problem:

1. In MVCC, how many threads participate in login() method? Is it the case that one thread does the read and writes a versioned update, but another thread merges the updated data *after* TX commit?

2. A somewhat dated http://www.jboss.org/community/docs/DOC-10266 wiki says there exists a faulty assumption about consistent ordering of synchronizations in Hibernate/JBC (problem #5). Has that been addressed? If not, could that be causing given problem?

3. Same wiki's problem #7:

Hibernate should either retry or JBossCache should fail silently on this. (Nikita: not sure what 'this' refers to) As long as the data is stored in the db correctly, failure putting the data in the cache could fail silently. Next time someone requests the entity, it'd be retrieved from db and put in the cache.

This paragraph seems to imply that it is normal that cache is not updated on insert of new UserSession during login(). However, it also expects subsequent User.getSessions() to result in a DB read (and a put into cache). But what I am seeing that User.getSessions() in getRestrictedData() results in a cache hit on a (stale) node containing empty set user.sessions. Should addSession() in login() result in User.sessions collection node being invalidated (to be populated during subsequent reads) or being updated with a new reference to UserSession node? Similarly, should addSession() result in put into UserSession entity cache, or is that put expected to occur only on subsequent read?

4. Finally, turning up debugging shows multitude of these 2 types of messages. These are emitted seemingly in failing and succeeding requests:

[3/2/09 16:27:38:268] DEBUG [d585d9d4-cc59-4b35-b717-d26c97db8f89,ltester-100000] org.jboss.cache.interceptors.InvocationContextInterceptor - FAIL_SILENTLY Option is present - suspending any ongoing transaction.
[3/2/09 16:27:38:269] DEBUG [76225fe7-1541-4960-9c2d-cdbe1330f5c5,ltester-100001] org.jboss.cache.invocation.CacheInvocationDelegate - putForExternalRead() called with Fqn /com/doppelganger/domain/User/userSessions/COLL/com.doppelganger.domain.User.userSessions#183 and this node already exists. This method is hence a no op.

Does the latter say that a collections cache node will not be updated because one already exists. What if existing node contains an empty collection but the candidate node contains a non-empty collection?

[dukehoops]

Following up my own post. It seems that:
- during login(), new UserSession; updated User.userSessions entity and collection aren’t put() into cache by design. (see #4 at the very bottom of the previous post). If my guess is correct, whose responsibility is to evict the existing (stale) user.sessions collection node from cache?
- Nothing evicts the empty PersistentSet collection entry already sitting in cache. So, on subsequent read request, an undesirable cache hit takes place. But why isn’t this happening with when testing with 1 user, or for every user when multiple threads are employed?

[brian.stansberry]

To answer some of your questions, using your numbering scheme:

1) There is just one thread.

2) It's been resolved with respect to JBossTS. That is, the assumption about ordering is still there, but the specific problem with JBossTS that made that assumption incorrect is fixed. What transaction manager are you using?

3) Will reply later.

4) I suspect the problem lies in this area. If putForExternalRead() is being called when there is already data present, it will *by design* result in nothing happening. The design intent is that whatever is there is the same as or newer than what the putForExternalRead() is attempting to cache. If that's not the case, something is wrong -- either the call shouldn't be a putForExternalRead or a call to clear out the old data should have happened and didn't.

[brian.stansberry]

To answer #3, my read of the Hibernate code tells me that when Hibernate flushes the session that was in effect when addSession() was called, the node in JBC will be removed. When you subsequently read the collection, it will be loaded from DB and the putForExternalRead will be called.

That read of the Hibernate code also ties to how I expected it to work.

[dukehoops]

Brian,

Firstly, thanks for your prompt replies.

I am using Bitronix TX Manager.

It is now pretty obvious that User.userSessions collection node is NOT getting evicted from cache when login() Session flushes or tx commits. If your read is that Hibernate code should be evicting this collection node, then that's where the problem is.

Could you please reference class/method where that decision (to evict) is being made? I will step through.

I wonder whether the fact that the collection node is created and should be evicted in the same Hibernate Session is relevant (and is source of the problem). Recall that login() essentially does this:

//check if user's already logged in

begin
session.open()

usr.getSessions().isEmpty() //AFAIK this populates cache with collection node with 0 elements

//insert new element into collection
usr.addSession(new UserSession()); //guess nothing is happening in cache here

//flush session
session.flush(); //as you say user.userSessions node should be evicted (but is NOT)

commit

Hmm....

Also, let's say the above is the problem. Why isn't this ever happening when only 1 user is involved, but happens for a random subset of users under load. If work on a given user is done by a distinct thread and there are no worker threads involved, why the different results? Perhaps something somewhere is forgetting to clear some ThreadLocal (HTTP threads are pooled by tomcat)

[brian.stansberry]

The collection eviction is done via a call to the org.hibernate.cache.access.CollectionRegionAccessStrategy interface's remove(Object) method. The Hibernate/JBC integration implements that by calling JBC's Cache.removeNode(Fqn) method.

Calls to CollectionRegionAccessStrategy.remove() are all made via org.hibernate.action.CollectionAction.evict(). That in turn is called by the execute() method of the various subclasses of CollectionAction.

The PFER call comes via org.hibernate.engine.loading.CollectionLoadContext.addCollectionToCache(...)

Above classes are all in the "core" module of Hibernate Core.

I agree that the fact this only happens under load certainly seems like a big clue. Just not sure what to make of it yet.

I don't have experience with the Bitronix TX Manager, so don't know if it would have the synchronization ordering issue. But if you were seeing that problem I'd think you'd have other issues less subtle than this one.

[dukehoops]

OK, thanks again. I've built a multithreaded unit test to try and narrow the problem down. Will post again when I find something of note.

[brian.stansberry]

Thanks much. If you can reproduce this narrowed down to something you can send me we'll see if I can add it to the test suite.

[dukehoops]

Ok, I was able to create a multithreaded JUnit test to fail (with just 4 threads).
A race condition seems to arise when multiple threads are trying to modify state of the same cache node(s). Here's the per-user test scenario:

public void run() {
 try {
 for (int i = 0; i < ITERATION_COUNT; i++) {
 login(userName);
 think();

 //get users
 getFriends2(userName);
 //readUserSession(userName);
 think();

 logout(userName);
 think();

 ++completedIterations;
 }

 } catch (Throwable t) {
 this.causeOfFailure = t;
 }
 }

If I omit getFriends2() -> test passes. Else, test fails.
If users participating in the test are NOT friends of each other (do not try to read each other's data) then test passes. Else, test fails.

getFriends() includes friends' login status. In other words User A will call User.getSessions() on user B if the 2 are friends.

Let's say user.userSessions#B is not in cache. Then A asks for B's info:

A gets B's data:
a1: userB.getSessions(); //will read from DB and put into cache

Simultaneously, B logs in:

B.login():
b1: self.getSessions(); //will read from DB and put into cache
b2: self.addSession(new UserSession()); //will invalidate user.userSessions#B

Seems like what's happening is that after both TXs are done, it is state from step 'a1' that ends up in cache.

Something like this order:

-a1 starts (cache miss, A is going to DB)
-b1
-b2
-a1 finished (A comes back from DB, inserts empty collection *after* B invalidated node in step b2)

Still not clear what the root cause is here. Some possibilities:
- my code
- hibernate core
- hibernate-jbc integration code
- jbc core

I guess the problem lies either with versioning (either Hibernate versioning or MVCC versioning) or (insufficient?) locking.

Side question on Synchronization ordering:
I looked at BTM source; seems like their Synchronization register is ordered:

private List keys = new ArrayList();
 private Map objects = new TreeMap();


 public Scheduler() {
 }

 public void add(Object obj, int position) {
 Integer key = new Integer(position);
 List synchronizationsList = (List) objects.get(key);
 if (synchronizationsList == null) {
 if (!keys.contains(key)) {
 keys.add(key);
 Collections.sort(keys);
 }
 synchronizationsList = new ArrayList();
 objects.put(key, synchronizationsList);
 }
 synchronizationsList.add(obj);
 }

You said previously that assumptions around synchronization ordering were fixed for JBossTS and JBC specifically. Was the fix to order synchronizations in TX manager impl?

The reason I ask is that Spring seems to use a Synchronization to close Hibernate Sessions. Is there an expectation that *that* syncrhonization fire *before* JBC's synchronization?

thanks
-nikita

[dukehoops]

Here's the test class:

/*
 * To change this template, choose Tools | Templates
 * and open the template in the editor.
 */
package com.doppelganger.service.userservice;

import com.doppelganger.domain.User;
import com.doppelganger.domain.UserSession;
import com.doppelganger.test.AbstractFunctionalTest;
import com.doppelganger.test.TestEntityFactory;
import com.doppelganger.test.service.DgTxTemplateAdapter;
import com.doppelganger.test.service.TransactionCallbackWithException;
import java.sql.Timestamp;
import java.util.HashSet;
import java.util.Set;
import java.util.UUID;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.TimeUnit;
import net.eviltwinstudios.common.CommonUtils;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.transaction.TransactionStatus;

/**
 * test cache consistency when many users login/read/logout in a loop
 * @author nikita
 */
public class MultiuserLoginTest extends AbstractFunctionalTest {

 final private int USER_COUNT = 4;
 final private int ITERATION_COUNT = 20;
 final private long THINK_TIME_MILLIS = 0;
 final private long LAUNCH_INTERVAL_MILLIS = 10;
 @Autowired
 private DgTxTemplateAdapter txTemplate;
 final private ExecutorService pool = Executors.newFixedThreadPool(USER_COUNT);
 final private Set<String> LTESTER_USERNAMES = new HashSet<String>();

 @Override
 protected void onSetUp() throws Exception {
 super.onSetUp();

 for (int i = 0; i < USER_COUNT; i++) {
 LTESTER_USERNAMES.add(TestEntityFactory.LOADTESTUSER_PREFIX + (100000 + i));
 }

 }

 public void testManyUsers() throws InterruptedException {

 Set<LtesterUserRunner> runners = new HashSet<LtesterUserRunner>();
 for (String userName : LTESTER_USERNAMES) {
 LtesterUserRunner r = new LtesterUserRunner(userName);
 runners.add(r);
 pool.execute(r);
 Thread.sleep(LAUNCH_INTERVAL_MILLIS); //rampup
 }

 assertEquals("not all user threads launched", USER_COUNT, runners.size());

 getLogger().info("all clients launched");

 pool.shutdown();
 boolean finishedInTime = pool.awaitTermination(5, TimeUnit.MINUTES);

 assertTrue("test took too long", finishedInTime);

 //check whether all runners suceeded
 for (LtesterUserRunner r : runners) {
 assertEquals("runner for user=" + r.getUserName() + " did not complete all iterations; cause=" +
 CommonUtils.stackTraceToString(r.getCauseOfFailure()),
 ITERATION_COUNT,
 r.getCompletedIterations());
 }
 }

 /**
 * login Ltester user into environment and check cache state
 * @param ltesterUserName
 */
 public void login(final String ltesterUserName) throws Exception {


 //add userSession
 final UserSession us1 = (UserSession) txTemplate.executeWithException(new TransactionCallbackWithException() {

 public Object doInTransactionWithException(TransactionStatus status) throws Exception {

 //add user session, throw exception if one does not exist
 final User usr = getUserDao().findByNameChecked(ltesterUserName);

 UserSession userSession = new UserSession(usr);
 userSession.setToken(UUID.randomUUID().toString());

 userSession.setLoginTime(new Timestamp(System.currentTimeMillis()));
 userSession.resetSessionTimeout(); //ok here

 //attach userSession to User
 usr.initCurrentUserSession(userSession);

 return userSession;

 }
 });

 //check that we can get at userSession
 final UserSession us2 = getCurrentUserSession(ltesterUserName);

 if (us2 == null) {
 throw new IllegalStateException("userSession null after successful login");
 }

 if (!us1.equals(us2)) {
 throw new IllegalStateException("us1 != us2");
 }
 }

 /**
 * read UserSessions of all test participants
 */
 public void readUserSessionsOfTesters() throws Exception {
 txTemplate.executeWithException(new TransactionCallbackWithException() {

 public Object doInTransactionWithException(TransactionStatus status) throws Exception {

 for (String userName : LTESTER_USERNAMES) {
 final User usr = getUserDao().findByNameChecked(userName);
 usr.getCurrentUserSession(); //read user session
 }
 return null;
 }
 });
 }

 /**
 *
 * @param ltesterUserName
 * @return current userSession or null
 */
 private UserSession getCurrentUserSession(final String ltesterUserName) throws Exception {

 return (UserSession) txTemplate.executeWithException(new TransactionCallbackWithException() {

 public Object doInTransactionWithException(TransactionStatus status) throws Exception {

 //add user session, throw exception if one does not exist
 final User usr = getUserDao().findByNameChecked(ltesterUserName);

 return usr.getCurrentUserSession();
 }
 });

 }

 public void logout(final String ltesterUserName) throws Exception {

 //remove userSession
 txTemplate.executeWithException(new TransactionCallbackWithException() {

 public Object doInTransactionWithException(TransactionStatus status) throws Exception {

 //remove user session; throw exception if one didn't exist
 final User usr = getUserDao().findByNameChecked(ltesterUserName);

 if (usr.getCurrentUserSession() == null) {
 throw new IllegalStateException("current userSession is null *before* logout; user=" + ltesterUserName);
 }
 usr.removeCurrentUserSession();

 return null;
 }
 });

 //check that we can no longer get at userSession
 UserSession us = getCurrentUserSession(ltesterUserName);

 if (us != null) {
 throw new IllegalStateException("userSession remains after logout: us=" + us);
 }
 }

 class LtesterUserRunner implements Runnable {

 final private String userName;
 private int completedIterations = 0;
 private Throwable causeOfFailure;

 public LtesterUserRunner(final String usrName) {
 userName = usrName;
 }

 public void run() {
 try {
 for (int i = 0; i < ITERATION_COUNT; i++) {
 login(userName);
 //loginWithTestService(userName);
 //loginWithService(userName);
 think();

 //get users
 //getFriends2(userName);
 readUserSessionsOfTesters();
 think();

 logout(userName);
 think();

 ++completedIterations;
 }

 } catch (Throwable t) {
 this.causeOfFailure = t;
 }
 }

 /**
 * @return the userName
 */
 public String getUserName() {
 return userName;
 }

 /**
 * @return the success
 */
 public boolean isSuccess() {
 return ITERATION_COUNT == getCompletedIterations();
 }

 /**
 * @return the completedIterations
 */
 public int getCompletedIterations() {
 return completedIterations;
 }

 /**
 * @return the causeOfFailure
 */
 public Throwable getCauseOfFailure() {
 return causeOfFailure;
 }
 }

 private void think() {
 try {
 Thread.sleep(THINK_TIME_MILLIS);
 } catch (InterruptedException ex) {
 throw new RuntimeException("sleep interrupted", ex);
 }
 }

}

and relevant Domain objects:

@Entity
@org.hibernate.annotations.Entity(dynamicUpdate = true, dynamicInsert = true)
@Table(name = "users")
@Cache(usage = CacheConcurrencyStrategy.TRANSACTIONAL)
public class User extends GeneratedHiLoKeyEntity {

private Set<UserSession> userSessions = new HashSet<UserSession>();

 /**
 * @return the userSessions
 */
 @OneToMany(mappedBy = "user")
 @Cascade({org.hibernate.annotations.CascadeType.ALL, org.hibernate.annotations.CascadeType.DELETE_ORPHAN})
 @LazyCollection(LazyCollectionOption.TRUE)
 @Cache(usage = CacheConcurrencyStrategy.TRANSACTIONAL)
 private Set<UserSession> getUserSessions() {
 return userSessions;
 }

 /**
 * @param userSessions the userSessions to set
 */
 private void setUserSessions(Set<UserSession> userSessions) {
 this.userSessions = userSessions;
 }

 @Transient
 public UserSession getCurrentUserSession() {
 final Set<UserSession> sessions = getUserSessions();
 return sessions.isEmpty() ? null : sessions.iterator().next();
 }

 /**
 * convenience method for linking User and currentUserSession
 */
 public void initCurrentUserSession(UserSession aUserSession) {
 assert aUserSession != null;

 if (!getUserSessions().isEmpty()) {
 throw new IllegalStateException("User already refers to a UserSession; call User.removeCurrentUserSession() first");
 }

 aUserSession.setUser(this);
 getUserSessions().add(aUserSession);

 touch(); //force version update
 }

 /**
 * removes pointer to currentUserSession (if any). NOTE: this will not
 * result in UserSession object being deleted from DB.
 * session.delete(UserSession) needs to be executed to achieve the latter.
 *
 * @return removed currentServerSession
 */
 public UserSession removeCurrentUserSession() {
 final UserSession us = getCurrentUserSession();
 if (us != null && getUserSessions().remove(us)) {
 us.setUser(null);
 this.touch(); //force version update
 }
 return us;
 }




}

@Entity
@org.hibernate.annotations.Entity(dynamicInsert = true, dynamicUpdate = true)
@Table(name = "user_sessions")
@Cache(usage = CacheConcurrencyStrategy.TRANSACTIONAL)
public class UserSession extends AbstractUserSession {

private User user;

 UserSession() {
 }

 public UserSession(User usr) {
 assert usr != null;
 setUser(usr);
 }

 @ManyToOne(fetch = FetchType.LAZY)
 @JoinColumn(unique = true, name = "userId")
 @NotNull
 @ForeignKey(name = "FK_USER_SESSION_TO_USER")
 public User getUser() {
 return user;
 }

 /**
 * @param user the user to set
 */
 void setUser(User user) {
 this.user = user;
 //touch();
 }
}

Note that I tried putting synchronized (STATIC_LOCK) around init/getCurrent/removeUserSession in User and the test still failed. I suppose that means that the failure takes place around synchronization at TX commit time, not when domain objects are accessed (which makes sense).

Will keep digging further, but would appreciate any thoughts, of course.

[brian.stansberry]

"dukehoops" wrote:
Ok, I was able to create a multithreaded JUnit test to fail (with just 4 threads).

Great! Can you send me that? My address is to the left.

I guess the problem lies either with versioning (either Hibernate versioning or MVCC versioning) or (insufficient?) locking.

I've think you've exposed a logical flaw with the locking -- either in the hibernate-jbc integration or with the basic design in hibernate core itself. With an entity this kind of thing would not be a problem because a database lock on the record would either 1) block b2 updating the entity until a's tx is done 2) block a1's read until b's tx is done. But with a collection there is no single database record that both tx's need to lock on.

You said previously that assumptions around synchronization ordering were fixed for JBossTS and JBC specifically. Was the fix to order synchronizations in TX manager impl?

Yes.

The reason I ask is that Spring seems to use a Synchronization to close Hibernate Sessions. Is there an expectation that *that* syncrhonization fire *before* JBC's synchronization?

If you could give me a link to the Spring code, that would be good. This doesn't sound like a problem though; the key thing is that the session is flushed to the database before JBC's Synchronization's beforeCompletion() is called. Hibernate's own CacheSynchroniztion handles that. Sounds like Spring is calling Session.close() which is a housekeeping operation that would come *after* the above.

[dukehoops]

Brian,

I pasted my test code in a post right before yours. Is that insufficient? Unfortunately, that test code does rely on some of our own TX management code (which extends Spring's) so it seems you'd have to modify this code, replacing our tx template objects with your own. Will that work for you?

[brian.stansberry]

Sure, the pasted code should be fine, thanks. I'd adapt this into the hibernate-jbc integration test suite, which has its own tx mgmt utilities, so the Spring thing shouldn't be a big deal.

[dukehoops]

Brian,

I didn't understand your comment above. Were you saying that you will take my test source and adapt it to hibernate-jbc test suite or were you suggesting I do it?

I took another look at hib-jbc project but could not find any examples of tests exercising hibernate and jbc *3*. I looked here:
http://anonsvn.jboss.org/repos/hibernate/core/trunk/cache-jbosscache2/

But this project uses jbc2, meaning (AFAIK):
-using jbc2-styled config
-using optimistic or pessimistic locking (and not MVCC).
In other words, it's not the same setup as one described above.

TransactionalAccess or OptimisticTransactionalAccess?
And that got me thinking of whether I am using correct TransactionalAccess class:

org.hibernate.cache.jbc2.access has two classes:
TransactionalAccessDelegate and OptimisticTransactionalDelegate. The latter does things like this:

Option opt = getDataVersionOption(version, version);
return CacheHelper.putForExternalRead(cache, regionFqn, key, value, opt);


Debugging tells me I am using TransactionalAccessDelegate. Shouldn't OptimisticTxDelegate be used since my Domain object do use Hibernate's @Version? Or is that irrelevant because the two choices translate to deprecated Optimistic or Pessimistic locking in JBC and we're using MVCC?


I also have caches configured as Srping Beans (with Configuration and RuntimeConfig also spring beans) and use org.jboss.cache.CacheFactory directly to build caches (as described in JBC3 User Guide). org.hibernate.cache.jbc2 on the other hand uses org.jboss.cache.CacheManager to do the same. The reason I went with that approach is that org.hibernate.cache.jbc2 seems to want to work of jbc2-styled treecache.xml config only and does not parse org.jboss.cache.config.Configuration

[dukehoops]

REPEATABLE_READ fails with 1 User

Now I am even more confused. I just changed jbc isolation from read_committed to repeatable_read and now this test fails with *1* user on the very first iteration:

Failure:

runner for user=ltester-100000 did not complete all iterations; cause=[ThreadId=1] userSession null after successful login; user=ltester-100000 java.lang.IllegalStateException: userSession null after successful login; user=ltester-100000 at com.doppelganger.service.userservice.MultiuserLoginTest.login(MultiuserLoginTest.java:120)

Test code:

 public void login(final String ltesterUserName) throws Exception {
 LOG.debug("begin actual login user=" + ltesterUserName);

 //add userSession
 final UserSession us1 = (UserSession) txTemplate.executeWithException(new TransactionCallbackWithException() {

 public Object doInTransactionWithException(TransactionStatus status) throws Exception {

 //add user session, throw exception if one does not exist
 LOG.debug("before findByName user=" + ltesterUserName);
 final User usr = getUserDao().findByNameChecked(ltesterUserName);

 UserSession userSession = new UserSession(usr);
 userSession.setToken(UUID.randomUUID().toString());

 userSession.setLoginTime(new Timestamp(System.currentTimeMillis()));
 userSession.resetSessionTimeout(); //ok here

 //attach userSession to User
 LOG.debug("before initCurrentUserSession user=" + ltesterUserName);
 usr.initCurrentUserSession(userSession);
 LOG.debug("after initCurrentUserSession user=" + ltesterUserName);

 return userSession;

 }
 });

 LOG.debug("end actual login user=" + ltesterUserName);

 //check that we can get at userSession
 final UserSession us2 = getCurrentUserSession(ltesterUserName);

 if (us2 == null) {
 throw new IllegalStateException("userSession null after successful login; user=" + ltesterUserName);
 }

 if (!us1.equals(us2)) {
 throw new IllegalStateException("us1 != us2");
 }
 }

Any ideas?