[AURORA-1607] Persistent "Error accessing PooledConnection. Connection is invalid" exceptions with DbTaskStore enabled

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Cannot Reproduce
• Sprint: Twitter Aurora Q1'16 Sprint 18
• Assignee: Zameer Manji
• Reporter: Zameer Manji
• Created: 02/Feb/16 23:46
• Updated: 01/Mar/16 22:22
• Resolved: 01/Mar/16 22:22

Description

Even after the resolution of AURORA-1596 (adding a ping query), I still see exceptions like this in the log:

Feb 02, 2016 11:24:01 PM com.google.common.util.concurrent.ServiceManager$ServiceListener failed
SEVERE: Service PreemptorService [FAILED] has failed in the RUNNING state.
org.apache.ibatis.exceptions.PersistenceException: 
### Error rolling back transaction.  Cause: java.sql.SQLException: Error accessing PooledConnection. Connection is invalid.
### Cause: java.sql.SQLException: Error accessing PooledConnection. Connection is invalid.
	at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:30)
	at org.apache.ibatis.session.defaults.DefaultSqlSession.rollback(DefaultSqlSession.java:216)
	at org.apache.ibatis.session.SqlSessionManager.rollback(SqlSessionManager.java:299)
	at org.mybatis.guice.transactional.TransactionalMethodInterceptor.invoke(TransactionalMethodInterceptor.java:116)
	at org.apache.aurora.common.inject.TimedInterceptor.invoke(TimedInterceptor.java:83)
	at org.apache.aurora.scheduler.storage.log.LogStorage.read(LogStorage.java:570)
	at org.apache.aurora.scheduler.storage.CallOrderEnforcingStorage.read(CallOrderEnforcingStorage.java:113)
	at org.apache.aurora.scheduler.preemptor.PendingTaskProcessor.run(PendingTaskProcessor.java:119)
	at org.apache.aurora.scheduler.preemptor.PreemptorModule$PreemptorService.runOneIteration(PreemptorModule.java:145)
	at com.google.common.util.concurrent.AbstractScheduledService$ServiceDelegate$Task.run(AbstractScheduledService.java:189)
	at com.google.common.util.concurrent.Callables$3.run(Callables.java:100)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
Caused by: java.sql.SQLException: Error accessing PooledConnection. Connection is invalid.
	at org.apache.ibatis.datasource.pooled.PooledConnection.checkConnection(PooledConnection.java:254)
	at org.apache.ibatis.datasource.pooled.PooledConnection.invoke(PooledConnection.java:243)
	at com.sun.proxy.$Proxy130.getAutoCommit(Unknown Source)
	at org.apache.ibatis.transaction.jdbc.JdbcTransaction.rollback(JdbcTransaction.java:79)
	at org.apache.ibatis.executor.BaseExecutor.rollback(BaseExecutor.java:249)
	at org.apache.ibatis.executor.CachingExecutor.rollback(CachingExecutor.java:119)
	at org.apache.ibatis.session.defaults.DefaultSqlSession.rollback(DefaultSqlSession.java:213)
	... 16 more

E0202 23:24:01.414 [PreemptorService RUNNING, GuavaUtils$LifecycleShutdownListener:53] Service: PreemptorService [FAILED] failed unexpectedly. Triggering shutdown. 
I0202 23:24:01.414 [PreemptorService RUNNING, Lifecycle:84] Shutting down application 

To me this signals a problem in the mybatis connection pool implementation. Enabling verbose logging in all database related code does not show anything obvious in the logs.

Issue Links

• relates to: AURORA-1596 Invalid connection error from MyBatis.