[
https://issues.apache.org/jira/browse/AURORA-1596?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15120547#comment-15120547
]
Zameer Manji commented on AURORA-1596:
--------------------------------------
I have enabled more logging on a cluster that is experiencing this issue and
this is what I have seen.
PooledConnection errors are correlated with exceptions from H2. After piping H2
tracing to SLF4J I see exceptions like:
{noformat}
E0128 00:14:50.680 [qtp1317442128-5964, TraceWriterAdapter:69] jdbc[18]
exception org.h2.jdbc.JdbcSQLException: Timeout trying to lock table
"JOB_INSTANCE_UPDATE_EVENTS"; SQL statement:
SELECT
u.id AS u_id,
u.update_id AS jusm_update_id,
u.user AS jusm_user,
max_status.status AS jusm_just_status,
min_ts.timestamp_ms AS jusm_just_created_timestamp_ms,
max_ts.timestamp_ms AS jusm_just_last_modified_timestamp_ms,
j.id AS jusm_jk_id,
j.role AS jusm_jk_role,
j.environment AS jusm_jk_environment,
j.name AS jusm_jk_name,
u.id AS jui_juse_id,
u.update_group_size AS jui_juse_update_group_size,
u.max_per_instance_failures AS jui_juse_max_per_instance_failures,
u.max_failed_instances AS jui_juse_max_failed_instances,
u.min_wait_in_instance_running_ms AS
jui_juse_min_wait_in_instance_running_ms,
u.rollback_on_failure AS jui_juse_rollback_on_failure,
u.wait_for_batch_completion AS jui_juse_wait_for_batch_completion,
u.block_if_no_pulses_after_ms AS jui_juse_block_if_no_pulses_after_ms,
u.id AS jui_id,
cn.id AS jui_ditc_id,
cn.task_config_row_id AS jui_ditc_task_config_row_id,
di.id AS jui_ditc_r_id,
di.first AS jui_ditc_r_first,
di.last AS jui_ditc_r_last,
co.id AS jui_iitc_id,
co.task_config_row_id AS jui_iitc_task_config_row_id,
ci.id AS jui_iitc_r_id,
ci.first AS jui_iitc_r_first,
ci.last AS jui_iitc_r_last,
io.id AS jui_juse_r_id,
io.first AS jui_juse_r_first,
io.last AS jui_juse_r_last
,
l.lock_token AS lock_token
FROM job_updates AS u
INNER JOIN job_keys AS j ON j.id = u.job_key_id
INNER JOIN
(
SELECT
e_s.update_row_id,
e_s.status
FROM job_update_events AS e_s
INNER JOIN
(
SELECT
update_row_id,
MAX(timestamp_ms) AS timestamp_ms
FROM job_update_events
GROUP BY update_row_id
) AS e_t ON e_t.update_row_id = e_s.update_row_id AND e_t.timestamp_ms =
e_s.timestamp_ms
) AS max_status ON max_status.update_row_id = u.id
INNER JOIN
(
SELECT
update_row_id,
MIN(timestamp_ms) AS timestamp_ms
FROM job_update_events
GROUP BY update_row_id
) AS min_ts ON min_ts.update_row_id = u.id
INNER JOIN
(
SELECT
update_row_id,
MAX(timestamp_ms) AS timestamp_ms
FROM
(
SELECT
update_row_id,
timestamp_ms
FROM job_update_events
UNION ALL
SELECT
update_row_id,
timestamp_ms
FROM job_instance_update_events
)
GROUP BY update_row_id
) AS max_ts ON max_ts.update_row_id = u.id
LEFT OUTER JOIN job_update_configs AS cn ON cn.update_row_id = u.id AND
cn.is_new = TRUE
LEFT OUTER JOIN job_update_configs AS co ON co.update_row_id = u.id AND
co.is_new = FALSE
LEFT OUTER JOIN job_update_configs_to_instances AS ci ON ci.config_id =
co.id
LEFT OUTER JOIN job_updates_to_desired_instances AS di ON di.update_row_id
= u.id
LEFT OUTER JOIN job_updates_to_instance_overrides AS io ON io.update_row_id
= u.id
LEFT OUTER JOIN job_update_locks AS l on l.update_row_id = u.id
WHERE
u.update_id = ?
AND j.role = ?
AND j.environment = ?
AND j.name = ? [50200-190]
at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
~[h2-1.4.190.jar:1.4.190]
at org.h2.message.DbException.get(DbException.java:179)
~[h2-1.4.190.jar:1.4.190]
at org.h2.message.DbException.get(DbException.java:155)
~[h2-1.4.190.jar:1.4.190]
at org.h2.table.RegularTable.doLock1(RegularTable.java:509)
~[h2-1.4.190.jar:1.4.190]
at org.h2.table.RegularTable.lock(RegularTable.java:472)
~[h2-1.4.190.jar:1.4.190]
at org.h2.table.TableFilter.lock(TableFilter.java:146)
~[h2-1.4.190.jar:1.4.190]
at org.h2.command.dml.Select.queryWithoutCache(Select.java:629)
~[h2-1.4.190.jar:1.4.190]
at org.h2.command.dml.Query.query(Query.java:322)
~[h2-1.4.190.jar:1.4.190]
at org.h2.command.dml.Query.query(Query.java:290)
~[h2-1.4.190.jar:1.4.190]
at
org.h2.command.dml.SelectUnion.queryWithoutCache(SelectUnion.java:194)
~[h2-1.4.190.jar:1.4.190]
at org.h2.command.dml.SelectUnion.query(SelectUnion.java:425)
~[h2-1.4.190.jar:1.4.190]
at org.h2.command.dml.Query.query(Query.java:290)
~[h2-1.4.190.jar:1.4.190]
at org.h2.index.ViewIndex.find(ViewIndex.java:272)
~[h2-1.4.190.jar:1.4.190]
at org.h2.index.ViewIndex.find(ViewIndex.java:177)
~[h2-1.4.190.jar:1.4.190]
at org.h2.index.BaseIndex.find(BaseIndex.java:127)
~[h2-1.4.190.jar:1.4.190]
at org.h2.index.IndexCursor.find(IndexCursor.java:159)
~[h2-1.4.190.jar:1.4.190]
at org.h2.table.TableFilter.next(TableFilter.java:329)
~[h2-1.4.190.jar:1.4.190]
at org.h2.command.dml.Select.queryGroup(Select.java:325)
~[h2-1.4.190.jar:1.4.190]
at org.h2.command.dml.Select.queryWithoutCache(Select.java:638)
~[h2-1.4.190.jar:1.4.190]
at org.h2.command.dml.Query.query(Query.java:322)
~[h2-1.4.190.jar:1.4.190]
at org.h2.command.dml.Query.query(Query.java:290)
~[h2-1.4.190.jar:1.4.190]
at org.h2.index.ViewIndex.find(ViewIndex.java:272)
~[h2-1.4.190.jar:1.4.190]
at org.h2.index.ViewIndex.find(ViewIndex.java:177)
~[h2-1.4.190.jar:1.4.190]
at org.h2.index.BaseIndex.find(BaseIndex.java:127)
~[h2-1.4.190.jar:1.4.190]
at org.h2.index.IndexCursor.find(IndexCursor.java:159)
~[h2-1.4.190.jar:1.4.190]
at org.h2.table.TableFilter.next(TableFilter.java:329)
~[h2-1.4.190.jar:1.4.190]
at org.h2.table.TableFilter.next(TableFilter.java:399)
~[h2-1.4.190.jar:1.4.190]
at org.h2.table.TableFilter.next(TableFilter.java:399)
~[h2-1.4.190.jar:1.4.190]
at org.h2.command.dml.Select.queryFlat(Select.java:531)
~[h2-1.4.190.jar:1.4.190]
at org.h2.command.dml.Select.queryWithoutCache(Select.java:643)
~[h2-1.4.190.jar:1.4.190]
at org.h2.command.dml.Query.query(Query.java:322)
~[h2-1.4.190.jar:1.4.190]
at org.h2.command.dml.Query.query(Query.java:290)
~[h2-1.4.190.jar:1.4.190]
at org.h2.command.dml.Query.query(Query.java:36)
~[h2-1.4.190.jar:1.4.190]
at org.h2.command.CommandContainer.query(CommandContainer.java:90)
~[h2-1.4.190.jar:1.4.190]
at org.h2.command.Command.executeQuery(Command.java:196)
~[h2-1.4.190.jar:1.4.190]
at
org.h2.jdbc.JdbcPreparedStatement.execute(JdbcPreparedStatement.java:192)
~[h2-1.4.190.jar:1.4.190]
at
org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:62)
[mybatis-3.3.0.jar:3.3.0]
at
org.apache.ibatis.executor.statement.RoutingStatementHandler.query(RoutingStatementHandler.java:78)
[mybatis-3.3.0.jar:3.3.0]
at
org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:62)
[mybatis-3.3.0.jar:3.3.0]
at
org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:303)
[mybatis-3.3.0.jar:3.3.0]
at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:154)
[mybatis-3.3.0.jar:3.3.0]
at
org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:102)
[mybatis-3.3.0.jar:3.3.0]
at
org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:82)
[mybatis-3.3.0.jar:3.3.0]
at
org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:120)
[mybatis-3.3.0.jar:3.3.0]
at
org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:113)
[mybatis-3.3.0.jar:3.3.0]
at
org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:73)
[mybatis-3.3.0.jar:3.3.0]
at sun.reflect.GeneratedMethodAccessor16.invoke(Unknown Source) ~[na:na]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
~[na:1.8.0_66-Tw8r9b2]
at java.lang.reflect.Method.invoke(Method.java:497)
~[na:1.8.0_66-Tw8r9b2]
at
org.apache.ibatis.session.SqlSessionManager$SqlSessionInterceptor.invoke(SqlSessionManager.java:334)
[mybatis-3.3.0.jar:3.3.0]
at com.sun.proxy.$Proxy63.selectOne(Unknown Source) [na:na]
at
org.apache.ibatis.session.SqlSessionManager.selectOne(SqlSessionManager.java:165)
[mybatis-3.3.0.jar:3.3.0]
at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:69)
[mybatis-3.3.0.jar:3.3.0]
at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:53)
[mybatis-3.3.0.jar:3.3.0]
at
org.apache.aurora.scheduler.storage.db.$Proxy73.selectDetails(Unknown Source)
[na:na]
at
org.apache.aurora.scheduler.storage.db.DbJobUpdateStore.fetchJobUpdateDetails(DbJobUpdateStore.java:206)
[aurora-119.jar:na]
at
org.apache.aurora.scheduler.storage.db.DbJobUpdateStore$$EnhancerByGuice$$c8de01a4.CGLIB$fetchJobUpdateDetails$5(<generated>)
[guice-3.0.jar:na]
at
org.apache.aurora.scheduler.storage.db.DbJobUpdateStore$$EnhancerByGuice$$c8de01a4$$FastClassByGuice$$31747421.invoke(<generated>)
[guice-3.0.jar:na]
at
com.google.inject.internal.cglib.proxy.$MethodProxy.invokeSuper(MethodProxy.java:228)
[guice-3.0.jar:na]
at
com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:72)
[guice-3.0.jar:na]
at
org.apache.aurora.common.inject.TimedInterceptor.invoke(TimedInterceptor.java:83)
[commons-119.jar:na]
at
com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:72)
[guice-3.0.jar:na]
at
com.google.inject.internal.InterceptorStackCallback.intercept(InterceptorStackCallback.java:52)
[guice-3.0.jar:na]
at
org.apache.aurora.scheduler.storage.db.DbJobUpdateStore$$EnhancerByGuice$$c8de01a4.fetchJobUpdateDetails(<generated>)
[guice-3.0.jar:na]
at
org.apache.aurora.scheduler.thrift.ReadOnlySchedulerImpl.lambda$getJobUpdateDetails$34(ReadOnlySchedulerImpl.java:317)
[aurora-119.jar:na]
at
org.apache.aurora.scheduler.storage.db.DbStorage.read(DbStorage.java:138)
~[aurora-119.jar:na]
at
org.apache.aurora.scheduler.storage.db.DbStorage$$EnhancerByGuice$$5befb341.CGLIB$read$5(<generated>)
~[guice-3.0.jar:na]
at
org.apache.aurora.scheduler.storage.db.DbStorage$$EnhancerByGuice$$5befb341$$FastClassByGuice$$bd486db3.invoke(<generated>)
~[guice-3.0.jar:na]
at
com.google.inject.internal.cglib.proxy.$MethodProxy.invokeSuper(MethodProxy.java:228)
[guice-3.0.jar:na]
at
com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:72)
[guice-3.0.jar:na]
at
org.mybatis.guice.transactional.TransactionalMethodInterceptor.invoke(TransactionalMethodInterceptor.java:101)
~[mybatis-guice-3.7.jar:3.7]
at
com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:72)
[guice-3.0.jar:na]
at
org.apache.aurora.common.inject.TimedInterceptor.invoke(TimedInterceptor.java:83)
[commons-119.jar:na]
at
com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:72)
[guice-3.0.jar:na]
at
com.google.inject.internal.InterceptorStackCallback.intercept(InterceptorStackCallback.java:52)
[guice-3.0.jar:na]
at
org.apache.aurora.scheduler.storage.db.DbStorage$$EnhancerByGuice$$5befb341.read(<generated>)
~[guice-3.0.jar:na]
at
org.apache.aurora.scheduler.storage.log.LogStorage.read(LogStorage.java:570)
~[aurora-119.jar:na]
at
org.apache.aurora.scheduler.storage.CallOrderEnforcingStorage.read(CallOrderEnforcingStorage.java:113)
~[aurora-119.jar:na]
at
org.apache.aurora.scheduler.thrift.ReadOnlySchedulerImpl.getJobUpdateDetails(ReadOnlySchedulerImpl.java:317)
[aurora-119.jar:na]
at
org.apache.aurora.scheduler.thrift.SchedulerThriftInterface.getJobUpdateDetails(SchedulerThriftInterface.java:1099)
~[aurora-119.jar:na]
at
org.apache.aurora.scheduler.thrift.SchedulerThriftInterface$$EnhancerByGuice$$cfdabfa.CGLIB$getJobUpdateDetails$17(<generated>)
~[guice-3.0.jar:na]
at
org.apache.aurora.scheduler.thrift.SchedulerThriftInterface$$EnhancerByGuice$$cfdabfa$$FastClassByGuice$$6ed696ca.invoke(<generated>)
~[guice-3.0.jar:na]
at
com.google.inject.internal.cglib.proxy.$MethodProxy.invokeSuper(MethodProxy.java:228)
[guice-3.0.jar:na]
at
com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:72)
[guice-3.0.jar:na]
at
org.apache.aurora.scheduler.thrift.aop.ThriftStatsExporterInterceptor.invoke(ThriftStatsExporterInterceptor.java:47)
~[aurora-119.jar:na]
at
com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:72)
[guice-3.0.jar:na]
at
org.apache.aurora.scheduler.thrift.aop.LoggingInterceptor.invoke(LoggingInterceptor.java:70)
~[aurora-119.jar:na]
at
com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:72)
[guice-3.0.jar:na]
at
org.apache.aurora.scheduler.thrift.aop.ServerInfoInterceptor.invoke(ServerInfoInterceptor.java:30)
~[aurora-119.jar:na]
at
com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:72)
[guice-3.0.jar:na]
at
com.google.inject.internal.InterceptorStackCallback.intercept(InterceptorStackCallback.java:52)
[guice-3.0.jar:na]
at
org.apache.aurora.scheduler.thrift.SchedulerThriftInterface$$EnhancerByGuice$$cfdabfa.getJobUpdateDetails(<generated>)
~[guice-3.0.jar:na]
at
org.apache.aurora.gen.ReadOnlyScheduler$Processor$getJobUpdateDetails.getResult(ReadOnlyScheduler.java:1171)
~[aurora-api-119.jar:na]
at
org.apache.aurora.gen.ReadOnlyScheduler$Processor$getJobUpdateDetails.getResult(ReadOnlyScheduler.java:1156)
~[aurora-api-119.jar:na]
at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39)
~[libthrift-0.9.1.jar:0.9.1]
at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39)
~[libthrift-0.9.1.jar:0.9.1]
at org.apache.thrift.server.TServlet.doPost(TServlet.java:83)
~[libthrift-0.9.1.jar:0.9.1]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
~[javax.servlet-api-3.1.0.jar:3.1.0]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
~[javax.servlet-api-3.1.0.jar:3.1.0]
at
com.google.inject.servlet.ServletDefinition.doService(ServletDefinition.java:263)
~[guice-servlet-3.0.jar:na]
at
com.google.inject.servlet.ServletDefinition.service(ServletDefinition.java:178)
~[guice-servlet-3.0.jar:na]
at
com.google.inject.servlet.ManagedServletPipeline.service(ManagedServletPipeline.java:91)
~[guice-servlet-3.0.jar:na]
at
com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:62)
~[guice-servlet-3.0.jar:na]
at
com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:168)
~[guice-servlet-3.0.jar:na]
at
com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58)
~[guice-servlet-3.0.jar:na]
at
com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:168)
~[guice-servlet-3.0.jar:na]
at
com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58)
~[guice-servlet-3.0.jar:na]
at
org.apache.aurora.scheduler.http.LeaderRedirectFilter.doFilter(LeaderRedirectFilter.java:64)
~[aurora-119.jar:na]
at
org.apache.aurora.scheduler.http.AbstractFilter.doFilter(AbstractFilter.java:44)
~[aurora-119.jar:na]
at
com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:163)
~[guice-servlet-3.0.jar:na]
at
com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58)
~[guice-servlet-3.0.jar:na]
at
org.apache.aurora.scheduler.http.HttpStatsFilter.doFilter(HttpStatsFilter.java:71)
~[aurora-119.jar:na]
at
org.apache.aurora.scheduler.http.AbstractFilter.doFilter(AbstractFilter.java:44)
~[aurora-119.jar:na]
at
com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:163)
~[guice-servlet-3.0.jar:na]
at
com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58)
~[guice-servlet-3.0.jar:na]
at
com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:168)
~[guice-servlet-3.0.jar:na]
at
com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58)
~[guice-servlet-3.0.jar:na]
at
com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:168)
~[guice-servlet-3.0.jar:na]
at
com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58)
~[guice-servlet-3.0.jar:na]
at
com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:168)
~[guice-servlet-3.0.jar:na]
at
com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58)
~[guice-servlet-3.0.jar:na]
at
com.google.inject.servlet.FilterDefinition.doFilter(FilterDefinition.java:168)
~[guice-servlet-3.0.jar:na]
at
com.google.inject.servlet.FilterChainInvocation.doFilter(FilterChainInvocation.java:58)
~[guice-servlet-3.0.jar:na]
at
com.google.inject.servlet.ManagedFilterPipeline.dispatch(ManagedFilterPipeline.java:118)
~[guice-servlet-3.0.jar:na]
at com.google.inject.servlet.GuiceFilter.doFilter(GuiceFilter.java:113)
~[guice-servlet-3.0.jar:na]
at
org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1668)
~[jetty-servlet-9.3.6.v20151106.jar:9.3.6.v20151106]
at
org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:581)
~[jetty-servlet-9.3.6.v20151106.jar:9.3.6.v20151106]
at
org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1158)
~[jetty-server-9.3.6.v20151106.jar:9.3.6.v20151106]
at
org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:511)
~[jetty-servlet-9.3.6.v20151106.jar:9.3.6.v20151106]
at
org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1090)
~[jetty-server-9.3.6.v20151106.jar:9.3.6.v20151106]
at
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
~[jetty-server-9.3.6.v20151106.jar:9.3.6.v20151106]
at
org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:52)
~[jetty-server-9.3.6.v20151106.jar:9.3.6.v20151106]
at
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:119)
~[jetty-server-9.3.6.v20151106.jar:9.3.6.v20151106]
at
org.eclipse.jetty.rewrite.handler.RewriteHandler.handle(RewriteHandler.java:318)
~[jetty-rewrite-9.3.6.v20151106.jar:9.3.6.v20151106]
at
org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:437)
~[jetty-server-9.3.6.v20151106.jar:9.3.6.v20151106]
at
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:119)
~[jetty-server-9.3.6.v20151106.jar:9.3.6.v20151106]
at org.eclipse.jetty.server.Server.handle(Server.java:517)
~[jetty-server-9.3.6.v20151106.jar:9.3.6.v20151106]
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:308)
~[jetty-server-9.3.6.v20151106.jar:9.3.6.v20151106]
at
org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:242)
~[jetty-server-9.3.6.v20151106.jar:9.3.6.v20151106]
at
org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:261)
~[jetty-io-9.3.6.v20151106.jar:9.3.6.v20151106]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
~[jetty-io-9.3.6.v20151106.jar:9.3.6.v20151106]
at
org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:75)
~[jetty-io-9.3.6.v20151106.jar:9.3.6.v20151106]
at
org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceAndRun(ExecuteProduceConsume.java:213)
~[jetty-util-9.3.6.v20151106.jar:9.3.6.v20151106]
at
org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:147)
~[jetty-util-9.3.6.v20151106.jar:9.3.6.v20151106]
at
org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:654)
~[jetty-util-9.3.6.v20151106.jar:9.3.6.v20151106]
at
org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:572)
~[jetty-util-9.3.6.v20151106.jar:9.3.6.v20151106]
at java.lang.Thread.run(Thread.java:745) ~[na:1.8.0_66-Tw8r9b2]
{noformat}
To me it seems that triggering a lock timeout causes the MyBatis
PooledConnection to be invalided.
I think this indicates a bug in the MyBatis connection pool and I think we
should switch to the C3P0 connection pool (which we already depend on):
http://www.mchange.com/projects/c3p0/
> Invalid connection error from TaskHistoryPruner when using DBTaskStore
> ----------------------------------------------------------------------
>
> Key: AURORA-1596
> URL: https://issues.apache.org/jira/browse/AURORA-1596
> Project: Aurora
> Issue Type: Bug
> Components: Scheduler
> Reporter: Joshua Cohen
> Assignee: Zameer Manji
>
> In a scheduler with the db task store enabled we're seeing this error causing
> frequent shutdowns:
> {noformat}
> Jan 26, 2016 3:30:00 PM
> com.google.common.util.concurrent.ServiceManager$ServiceListener failed
> SEVERE: Service TaskHistoryPruner [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.storage.Storage$Util.fetchTasks(Storage.java:297)
> at
> org.apache.aurora.scheduler.pruning.TaskHistoryPruner.lambda$registerInactiveTask$103(TaskHistoryPruner.java:167)
> at
> org.apache.aurora.scheduler.pruning.TaskHistoryPruner.lambda$failureNotifyingRunnable$101(TaskHistoryPruner.java:144)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
> 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.$Proxy131.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)
> ... 15 more
> E0126 15:30:00.202 [AsyncProcessor-4,
> GuavaUtils$LifecycleShutdownListener:54] Service: TaskHistoryPruner [FAILED]
> failed unexpectedly. Triggering shutdown.
> I0126 15:30:00.202 [AsyncProcessor-4, Lifecycle:84] Shutting down application
> I0126 15:30:00.202 [AsyncProcessor-4,
> ShutdownRegistry$ShutdownRegistryImpl:77] Executing 2 shutdown commands.
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
