Problem: @AfterThrowing with JPA in a scheduled method

[alpheratz]

If I uncomment the first line of the getWeather() method so that a RollbackException is thrown, I see the expected behaviour (ie GetWeatherTxLoggerAspect.logException() is executed).

If I leave the line commented out, but force the underlying database to barf (typically by ensuring that windDAO.save barfs with a duplicate key exception--ie by assserting a dummy record into the respective table) the logging does not get performed.

it seems to me that getWeather() is being wrapped in a transaction and it is this wrapper that actually throws the exception. The question then becomes: how do I actually get hold of the fact that an exception occurred so that I can log it as I want to?

Perhaps I should advise org.springframework.scheduling.timer.TimerFactoryB ean?

Any suggestions gratefully accepted.

Cheers,

Alph.

=== collatoral follows: ===

  @Transactional(propagation = Propagation.REQUIRES_NEW)
  public void getWeather()
    {
//    if (1 == 1) throw new RollbackException("WHAT WHAT WHAT!!!");
 
    // at startup, find most recent timestamp
    if (lastRTs == null)
      {
      lastRTs = timestampDAO.findLatest().getStamp();
      logger.info("Found most recent Timestamp entry: " + lastRTs);
      }

    Reading r = getter.doGet();
    if (r != null)
      {
      Date rts = r.getTimestamp();
      logger.info("NEW timestamp: " + rts + "; OLD=" + lastRTs);
      if (!rts.equals(lastRTs))
        {
        lastRTs = rts;
        Timestamp ts = new Timestamp(rts);
        timestampDAO.save(ts);
        humidityDAO.save(new Humidity(ts, 0, location, r.getHumidity()));
        temperatureDAO
            .save(new Temperature(ts, 0, location, r.getTemperature()));
        windDAO.save(new Wind(ts, 0, location, r.getSpeed(), r.getDirection()));
        }
      }
    }

Logger aspect is:

...
@Aspect
public class GetWeatherTxLoggerAspect
  {
  @AfterThrowing(throwing = "t", pointcut = "execution(* au.com.transentia.weather.timer.GetWeatherTask.getWeather(..))")
  public void logException(Throwable t)
    {
    logger.error("***Logging Exception from GetWeatherTask.getWeather(): " + t, t);
    }

  ...
  }

Configuration of the aspect stuff is:

..
<aop:aspectj-autoproxy />

<bean id="getWeatherTxLogger"
   class="au.com.transentia.weather.timer.GetWeatherTxLoggerAspect" />
...

Configuration of the Timer:

...
	<bean id="WeatherTask"
		class="au.com.transentia.weather.timer.GetWeatherTask">
		<property name="getter" ref="DummyBOMGetter" />
		<property name="timestampDAO" ref="timestampDAO" />
		<property name="temperatureDAO" ref="temperatureDAO" />
		<property name="humidityDAO" ref="humidityDAO" />
		<property name="windDAO" ref="windDAO" />
	</bean>

	<bean id="getWeatherMethodInvoker"
		class="org.springframework.scheduling.timer.MethodInvokingTimerTaskFactoryBean">
		<property name="targetObject" ref="WeatherTask" />
		<property name="targetMethod" value="getWeather" />
	</bean>

	<bean id="scheduledTask"
		class="org.springframework.scheduling.timer.ScheduledTimerTask">
		<!-- wait 10 seconds before starting repeated execution -->
		<property name="delay" value="10000" />
		<!-- run every 5 mins -->
		<property name="period" value="10000" />
		<property name="timerTask" ref="getWeatherMethodInvoker" />
	</bean>

	<bean
		class="org.springframework.scheduling.timer.TimerFactoryBean">
		<property name="scheduledTimerTasks">
			<list>
				<ref bean="scheduledTask" />
			</list>
		</property>
	</bean>

Stacktrace excerpt for ('bad' behaviour) persistence exception case:

0:36:02,640 INFO  [STDOUT] [TopLink Warning]: 2006.12.02 08:36:02.640--UnitOfWork(12721409)--Thread(Thread[org.springframework.scheduling.timer.TimerFactoryBean,5,jboss])--Exception [TOPLINK-4002] (Oracle TopLink Essentials - 9.1 (Build b25)): oracle.toplink.essentials.exceptions.DatabaseException
Internal Exception: com.mysql.jdbc.exceptions.MySQLIntegrityConstraintViolationException: Duplicate entry '1313' for key 1Error Code: 1062
Call:INSERT INTO WIND (ID, PERIOD, DIRECTION, SPEED, loc_lat, loc_long, TIMESTAMP_ID) VALUES (?, ?, ?, ?, ?, ?, ?)
	bind => [1313, 0, NE, 8.8, 50.0, 50.0, 1310]
Query:InsertObjectQuery(au.com.transentia.weather.model.entity.Wind@a0187c)
20:36:02,671 ERROR [MethodInvokingTimerTaskFactoryBean] Invocation of method 'getWeather' on target object [au.com.transentia.weather.timer.GetWeatherTask@748417] failed
java.lang.reflect.InvocationTargetException
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:585)
	at org.springframework.util.MethodInvoker.invoke(MethodInvoker.java:270)
	at org.springframework.scheduling.support.MethodInvokingRunnable.run(MethodInvokingRunnable.java:79)
	at org.springframework.scheduling.timer.DelegatingTimerTask.run(DelegatingTimerTask.java:60)
	at java.util.TimerThread.mainLoop(Timer.java:512)
	at java.util.TimerThread.run(Timer.java:462)
Caused by: org.springframework.transaction.UnexpectedRollbackException: JPA transaction unexpectedly rolled back (maybe marked rollback-only after a failed operation); nested exception is javax.persistence.RollbackException: Exception [TOPLINK-4002] (Oracle TopLink Essentials - 9.1 (Build b25)): oracle.toplink.essentials.exceptions.DatabaseException
Internal Exception: com.mysql.jdbc.exceptions.MySQLIntegrityConstraintViolationException: Duplicate entry '1313' for key 1Error Code: 1062
Call:INSERT INTO WIND (ID, PERIOD, DIRECTION, SPEED, loc_lat, loc_long, TIMESTAMP_ID) VALUES (?, ?, ?, ?, ?, ?, ?)
	bind => [1313, 0, NE, 8.8, 50.0, 50.0, 1310]
Query:InsertObjectQuery(au.com.transentia.weather.model.entity.Wind@a0187c)
	at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:422)
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:611)
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:581)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:307)
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:117)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:176)
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:176)
	at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:615)
	at au.com.transentia.weather.timer.GetWeatherTask$$EnhancerByCGLIB$$f7662012.getWeather(<generated>)
	... 9 more


SNIP...SNIP...

Caused by: com.mysql.jdbc.exceptions.MySQLIntegrityConstraintViolationException: Duplicate entry '1313' for key 1
	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:931)

[karldmoore]

This could be something to do with ordering. I've had problems before when two aspects are applied. If the order is Transaction then Logging, a manually thrown exception would be logged. If you are using something like Hibernate, the exception would only be thrown when the session is flushed, more than likely when the transaction is committing. To test this you could do a flush after the save and the logging should be there.

There is some information in the manual about ordering of advice.
http://www.springframework.org/docs/...dvice-ordering
http://www.springframework.org/docs/...just-tx-advice

This might also be useful.
http://forum.springframework.org/sho...er+transaction

[alpheratz]

Many thanks, much appreciated!

I knew about ordering, I just didn't think that it applied to the situation I had.

Alph

[karldmoore]

Many thanks, much appreciated!
I knew about ordering, I just didn't think that it applied to the situation I had.

I have to admit it caught me out at first, glad you sorted it anyway!
Good luck.

Karl