Re: tasks will not run more often than leaseTime minutes

[Anil Gangolli]

I am not seeing any flush() on the persistence strategy in this code 
path at all, which (assuming READ_COMMITTED transaction isolation) 
suggests that there may also not be proper exclusion across multiple 
threads/hosts.   A flush() would be needed on registering the lease as 
well as releasing the lease.   I think in this case the manager 
(ThreadManager) actually should be doing this.  Allan, if you're around 
can you verify ?

Anil Gangolli wrote:

We should look for a missing commit there.   I think the connection 
pool does a rollback each time the connection is released back to the 
pool to safeguard against uncommitted work being committed by the next 
caller claiming the connection.  My guess is we're seeing that.

Looking at RollerTaskWithLeasing.java it looks like what is happening 
is it is explicitly calling WebloggerFactory.getWeblogger().release() 
and this may be causing the connection release before the update gets 
committed.


--a.


Dick Davies wrote:
OK, following on from yesterdays posts about scheduled tasks not
running (https://issues.apache.org/roller/browse/ROL-1760) ,
I've

1. set the timestamps in roller_tasklock to hundredths of a second 
precisison
2. cleared out that table
3. redeployed roller

and tasks are now running, with one caveat; our tasks won't run more
often than every leaseTime minutes.

After a bit more digging, we found our
JPAThreadManagerImpl.unregisterLease() method is not updating the
database,
so any lease that is successfully taken out are kept , blocking that
task from running, until they expire.

In this case , the JPA-generated SQL looks ok, but the roller logs
show what looks like a transaction rolling back:

DEBUG 2008-11-21 11:47:00,097 CommonsLogFactory$LogAdapter:trace -
Executing query: [UPDATE TaskLock t SET t.timeLeased=?1 WHERE t.
name=?2 AND t.clientId=?3] with parameters: {3=ScheduledEntriesTask,
2=0, 1=devel-roller01}
DEBUG 2008-11-21 11:47:00,097 CommonsLogFactory$LogAdapter:trace - <t
6810846, conn 4959010> executing prepstmnt 20488940 UPDATE ro
ller_tasklock t0 SET timeleased = ? WHERE (t0.name = ? AND t0.client =
?) [params=(int) 0, (String) ScheduledEntriesTask, (String)
devel-roller01]
DEBUG 2008-11-21 11:47:00,098 CommonsLogFactory$LogAdapter:trace - <t
6810846, conn 4959010> [0 ms] spent
DEBUG 2008-11-21 11:47:00,098 RollerTaskWithLeasing:run -
ScheduledEntriesTask: Lease released, task finished
DEBUG 2008-11-21 11:47:00,109 CommonsLogFactory$LogAdapter:trace - <t
6810846, conn 4959010> [10 ms] rollback  *******
DEBUG 2008-11-21 11:47:00,109 CommonsLogFactory$LogAdapter:trace - <t
6810846, conn 4959010> [0 ms] close

Is the line flagged '******' a transaction rolling back, or do I not
understand JPA at all?

If so, does anyone have any clue where I start looking to find out why
JPA did that?
I suppose I could work around this by setting leaseTime == interval,
but this is a multi-server cluster
and I've got enough headaches without adding race conditions into the 
mix :)

Thanks (filed this as https://issues.apache.org/roller/browse/ROL-1761).