aurora-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Zameer Manji (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (AURORA-1596) Invalid connection error from TaskHistoryPruner when using DBTaskStore
Date Thu, 28 Jan 2016 01:01:57 GMT

    [ 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)

Mime
View raw message