You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@aurora.apache.org by Mohit Jaggi <mo...@uber.com> on 2017/12/22 19:25:00 UTC
"Error accessing PooledConnection. Connection is invalid.
Folks,
While running load tests on Aurora I see the following. What does it mean?
This <https://pastebin.com/cy0CXgMR> is the new code I added (we discussed
this a few weeks ago) to decline incoming update API calls when Aurora is
slowing down(not triggered in this case as this is a get call). The
following exceptions were seen earlier w/o my code change and appear
unrelated to the change. I also saw these during previous outages and want
to understand what is going on.
Mohit.
------- Exception -----
Dec 20 16:57:46 node64 aurora-scheduler[78639]: W1220 16:57:46.061
[qtp337673094-129204, LoggingInterceptor:106] Uncaught exception while
handling getJobUpdateDetails(null, JobUpdateQuery(role:test-uber-xxx-2,
key:null, jobKey:null, user:null, updateStatuses:[], offset:0, limit:0))
org.apache.ibatis.exceptions.PersistenceException:
Dec 20 16:57:46 node64 aurora-scheduler[78639]: ### Error rolling back
transaction. Cause: java.sql.SQLException: Error accessing
PooledConnection. Connection is invalid.
Dec 20 16:57:46 node64 aurora-scheduler[78639]: ### Cause:
java.sql.SQLException: Error accessing PooledConnection. Connection is
invalid.
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:30)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
org.apache.ibatis.session.defaults.DefaultSqlSession.rollback(DefaultSqlSession.java:244)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
org.apache.ibatis.session.SqlSessionManager.rollback(SqlSessionManager.java:315)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
org.mybatis.guice.transactional.TransactionalMethodInterceptor.invoke(TransactionalMethodInterceptor.java:116)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
org.apache.aurora.common.inject.TimedInterceptor.invoke(TimedInterceptor.java:83)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
org.apache.aurora.scheduler.storage.log.LogStorage.read(LogStorage.java:562)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
org.apache.aurora.scheduler.storage.CallOrderEnforcingStorage.read(CallOrderEnforcingStorage.java:113)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
org.apache.aurora.scheduler.thrift.ReadOnlySchedulerImpl.getJobUpdateDetails(ReadOnlySchedulerImpl.java:327)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
org.apache.aurora.scheduler.thrift.SchedulerThriftInterface.getJobUpdateDetails(SchedulerThriftInterface.java:1133)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
org.apache.aurora.scheduler.thrift.aop.ThrottlingInterceptor.invoke(ThrottlingInterceptor.java:122)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
org.apache.aurora.scheduler.thrift.aop.ThriftStatsExporterInterceptor.invoke(ThriftStatsExporterInterceptor.java:68)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
org.apache.aurora.scheduler.thrift.aop.LoggingInterceptor.invoke(LoggingInterceptor.java:98)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
org.apache.aurora.scheduler.thrift.aop.ServerInfoInterceptor.invoke(ServerInfoInterceptor.java:30)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
org.apache.aurora.gen.ReadOnlyScheduler$Processor$getJobUpdateDetails.getResult(ReadOnlyScheduler.java:1156)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
org.apache.aurora.gen.ReadOnlyScheduler$Processor$getJobUpdateDetails.getResult(ReadOnlyScheduler.java:1141)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
org.apache.aurora.scheduler.http.api.TContentAwareServlet.doPost(TContentAwareServlet.java:154)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
------- AopModule now includes ThrottlingInterceptor
<https://pastebin.com/cy0CXgMR> at the end -----
/**
* Binding module for AOP-style decorations of the thrift API.
*/
public class AopModule extends AbstractModule {
private static final Matcher<? super Class<?>> THRIFT_IFACE_MATCHER =
Matchers.subclassesOf(AnnotatedAuroraAdmin.class)
.and(Matchers.annotatedWith(DecoratedThrift.class));
@Override
protected void configure() {
// Layer ordering:
// APIVersion -> Log -> StatsExporter -> SchedulerThriftInterface
// It's important for this interceptor to be registered first to
ensure it's at the 'top' of
// the stack and the standard message is always applied.
bindThriftDecorator(new ServerInfoInterceptor());
bindThriftDecorator(new LoggingInterceptor());
bindThriftDecorator(new ThriftStatsExporterInterceptor());
bindThriftDecorator(new ThrottlingInterceptor());
}
private void bindThriftDecorator(MethodInterceptor interceptor) {
bindThriftDecorator(binder(), THRIFT_IFACE_MATCHER, interceptor);
}
@VisibleForTesting
static void bindThriftDecorator(
Binder binder,
Matcher<? super Class<?>> classMatcher,
MethodInterceptor interceptor) {
binder.bindInterceptor(
classMatcher,
Matchers.returns(Matchers.subclassesOf(Response.class)),
interceptor);
binder.requestInjection(interceptor);
}
}
Re: "Error accessing PooledConnection. Connection is invalid.
Posted by Mohit Jaggi <mo...@uber.com>.
It is not clear what the cause is. Is it just high load? Yes, eventually,
we will move to 0.19.x but that will take a while.
On Sat, Dec 23, 2017 at 2:06 AM, Stephan Erb <st...@blue-yonder.com>
wrote:
> Hi Mohit,
>
>
>
> I believe you are running into a form of https://issues.apache.org/
> jira/browse/AURORA-1596. Assuming it is the same cause, you might try to
> increase the lock timeout introduced in the linked issue.
>
>
>
> As a much more viable solution, I would recommend to update to 0.19
> though: Aurora does no longer use H2 as the backend for its internal
> storage. Besides eliminating the mentioned error, it should also lead to
> significant performance improvements.
>
>
>
> Best regards,
>
> Stephan
>
>
>
> *From: *Mohit Jaggi <mo...@uber.com>
> *Reply-To: *"user@aurora.apache.org" <us...@aurora.apache.org>
> *Date: *Friday, 22. December 2017 at 20:25
> *To: *"user@aurora.apache.org" <us...@aurora.apache.org>
> *Subject: *"Error accessing PooledConnection. Connection is invalid.
>
>
>
> Folks,
>
> While running load tests on Aurora I see the following. What does it mean?
> This <https://pastebin.com/cy0CXgMR> is the new code I added (we
> discussed this a few weeks ago) to decline incoming update API calls when
> Aurora is slowing down(not triggered in this case as this is a get call).
> The following exceptions were seen earlier w/o my code change and appear
> unrelated to the change. I also saw these during previous outages and want
> to understand what is going on.
>
>
>
> Mohit.
>
>
>
> ------- Exception -----
>
>
>
> Dec 20 16:57:46 node64 aurora-scheduler[78639]: W1220 16:57:46.061
> [qtp337673094-129204, LoggingInterceptor:106] Uncaught exception while
> handling getJobUpdateDetails(null, JobUpdateQuery(role:test-uber-xxx-2,
> key:null, jobKey:null, user:null, updateStatuses:[], offset:0, limit:0))
> org.apache.ibatis.exceptions.PersistenceException:
>
> Dec 20 16:57:46 node64 aurora-scheduler[78639]: ### Error rolling back
> transaction. Cause: java.sql.SQLException: Error accessing
> PooledConnection. Connection is invalid.
>
> Dec 20 16:57:46 node64 aurora-scheduler[78639]: ### Cause:
> java.sql.SQLException: Error accessing PooledConnection. Connection is
> invalid.
>
> Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
> org.apache.ibatis.exceptions.ExceptionFactory.wrapException(
> ExceptionFactory.java:30)
>
> Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
> org.apache.ibatis.session.defaults.DefaultSqlSession.
> rollback(DefaultSqlSession.java:244)
>
> Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
> org.apache.ibatis.session.SqlSessionManager.rollback(
> SqlSessionManager.java:315)
>
> Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at org.mybatis.guice.
> transactional.TransactionalMethodInterceptor.invoke(
> TransactionalMethodInterceptor.java:116)
>
> Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
> org.apache.aurora.common.inject.TimedInterceptor.
> invoke(TimedInterceptor.java:83)
>
> Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
> org.apache.aurora.scheduler.storage.log.LogStorage.read(
> LogStorage.java:562)
>
> Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
> org.apache.aurora.scheduler.storage.CallOrderEnforcingStorage.read(
> CallOrderEnforcingStorage.java:113)
>
> Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
> org.apache.aurora.scheduler.thrift.ReadOnlySchedulerImpl.
> getJobUpdateDetails(ReadOnlySchedulerImpl.java:327)
>
> Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
> org.apache.aurora.scheduler.thrift.SchedulerThriftInterface.
> getJobUpdateDetails(SchedulerThriftInterface.java:1133)
>
> Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
> org.apache.aurora.scheduler.thrift.aop.ThrottlingInterceptor.invoke(
> ThrottlingInterceptor.java:122)
>
> Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
> org.apache.aurora.scheduler.thrift.aop.ThriftStatsExporterInterceptor
> .invoke(ThriftStatsExporterInterceptor.java:68)
>
> Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
> org.apache.aurora.scheduler.thrift.aop.LoggingInterceptor.
> invoke(LoggingInterceptor.java:98)
>
> Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
> org.apache.aurora.scheduler.thrift.aop.ServerInfoInterceptor.invoke(
> ServerInfoInterceptor.java:30)
>
> Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
> org.apache.aurora.gen.ReadOnlyScheduler$Processor$
> getJobUpdateDetails.getResult(ReadOnlyScheduler.java:1156)
>
> Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
> org.apache.aurora.gen.ReadOnlyScheduler$Processor$
> getJobUpdateDetails.getResult(ReadOnlyScheduler.java:1141)
>
> Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at org.apache.thrift.
> ProcessFunction.process(ProcessFunction.java:39)
>
> Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at org.apache.thrift.
> TBaseProcessor.process(TBaseProcessor.java:39)
>
> Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at
> org.apache.aurora.scheduler.http.api.TContentAwareServlet.
> doPost(TContentAwareServlet.java:154)
>
> Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at javax.servlet.http.
> HttpServlet.service(HttpServlet.java:707)
>
> Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at javax.servlet.http.
> HttpServlet.service(HttpServlet.java:790)
>
>
>
> ------- AopModule now includes ThrottlingInterceptor
> <https://pastebin.com/cy0CXgMR> at the end -----
>
>
>
>
> */** * Binding module for AOP-style decorations of the thrift API. */*public class AopModule extends AbstractModule {
>
> private static final Matcher<? super Class<?>> *THRIFT_IFACE_MATCHER *=
> Matchers.*subclassesOf*(AnnotatedAuroraAdmin.class)
> .and(Matchers.*annotatedWith*(DecoratedThrift.class));
>
> @Override
> protected void configure() {
> // Layer ordering:
> // APIVersion -> Log -> StatsExporter -> SchedulerThriftInterface
>
> // It's important for this interceptor to be registered first to ensure it's at the 'top' of
> // the stack and the standard message is always applied.
> bindThriftDecorator(new ServerInfoInterceptor());
>
> bindThriftDecorator(new LoggingInterceptor());
> bindThriftDecorator(new ThriftStatsExporterInterceptor());
> bindThriftDecorator(new ThrottlingInterceptor());
> }
>
> private void bindThriftDecorator(MethodInterceptor interceptor) {
> *bindThriftDecorator*(binder(), *THRIFT_IFACE_MATCHER*, interceptor);
> }
>
> @VisibleForTesting
> static void bindThriftDecorator(
> Binder binder,
> Matcher<? super Class<?>> classMatcher,
> MethodInterceptor interceptor) {
>
> binder.bindInterceptor(
> classMatcher,
> Matchers.*returns*(Matchers.*subclassesOf*(Response.class)),
> interceptor);
> binder.requestInjection(interceptor);
> }
> }
>
>
Re: "Error accessing PooledConnection. Connection is invalid.
Posted by Stephan Erb <st...@blue-yonder.com>.
Hi Mohit,
I believe you are running into a form of https://issues.apache.org/jira/browse/AURORA-1596. Assuming it is the same cause, you might try to increase the lock timeout introduced in the linked issue.
As a much more viable solution, I would recommend to update to 0.19 though: Aurora does no longer use H2 as the backend for its internal storage. Besides eliminating the mentioned error, it should also lead to significant performance improvements.
Best regards,
Stephan
From: Mohit Jaggi <mo...@uber.com>
Reply-To: "user@aurora.apache.org" <us...@aurora.apache.org>
Date: Friday, 22. December 2017 at 20:25
To: "user@aurora.apache.org" <us...@aurora.apache.org>
Subject: "Error accessing PooledConnection. Connection is invalid.
Folks,
While running load tests on Aurora I see the following. What does it mean? This<https://pastebin.com/cy0CXgMR> is the new code I added (we discussed this a few weeks ago) to decline incoming update API calls when Aurora is slowing down(not triggered in this case as this is a get call). The following exceptions were seen earlier w/o my code change and appear unrelated to the change. I also saw these during previous outages and want to understand what is going on.
Mohit.
------- Exception -----
Dec 20 16:57:46 node64 aurora-scheduler[78639]: W1220 16:57:46.061 [qtp337673094-129204, LoggingInterceptor:106] Uncaught exception while handling getJobUpdateDetails(null, JobUpdateQuery(role:test-uber-xxx-2, key:null, jobKey:null, user:null, updateStatuses:[], offset:0, limit:0)) org.apache.ibatis.exceptions.PersistenceException:
Dec 20 16:57:46 node64 aurora-scheduler[78639]: ### Error rolling back transaction. Cause: java.sql.SQLException: Error accessing PooledConnection. Connection is invalid.
Dec 20 16:57:46 node64 aurora-scheduler[78639]: ### Cause: java.sql.SQLException: Error accessing PooledConnection. Connection is invalid.
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:30)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at org.apache.ibatis.session.defaults.DefaultSqlSession.rollback(DefaultSqlSession.java:244)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at org.apache.ibatis.session.SqlSessionManager.rollback(SqlSessionManager.java:315)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at org.mybatis.guice.transactional.TransactionalMethodInterceptor.invoke(TransactionalMethodInterceptor.java:116)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at org.apache.aurora.common.inject.TimedInterceptor.invoke(TimedInterceptor.java:83)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at org.apache.aurora.scheduler.storage.log.LogStorage.read(LogStorage.java:562)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at org.apache.aurora.scheduler.storage.CallOrderEnforcingStorage.read(CallOrderEnforcingStorage.java:113)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at org.apache.aurora.scheduler.thrift.ReadOnlySchedulerImpl.getJobUpdateDetails(ReadOnlySchedulerImpl.java:327)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at org.apache.aurora.scheduler.thrift.SchedulerThriftInterface.getJobUpdateDetails(SchedulerThriftInterface.java:1133)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at org.apache.aurora.scheduler.thrift.aop.ThrottlingInterceptor.invoke(ThrottlingInterceptor.java:122)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at org.apache.aurora.scheduler.thrift.aop.ThriftStatsExporterInterceptor.invoke(ThriftStatsExporterInterceptor.java:68)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at org.apache.aurora.scheduler.thrift.aop.LoggingInterceptor.invoke(LoggingInterceptor.java:98)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at org.apache.aurora.scheduler.thrift.aop.ServerInfoInterceptor.invoke(ServerInfoInterceptor.java:30)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at org.apache.aurora.gen.ReadOnlyScheduler$Processor$getJobUpdateDetails.getResult(ReadOnlyScheduler.java:1156)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at org.apache.aurora.gen.ReadOnlyScheduler$Processor$getJobUpdateDetails.getResult(ReadOnlyScheduler.java:1141)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at org.apache.aurora.scheduler.http.api.TContentAwareServlet.doPost(TContentAwareServlet.java:154)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
Dec 20 16:57:46 node64 aurora-scheduler[78639]: #011at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
------- AopModule now includes ThrottlingInterceptor<https://pastebin.com/cy0CXgMR> at the end -----
/**
* Binding module for AOP-style decorations of the thrift API.
*/
public class AopModule extends AbstractModule {
private static final Matcher<? super Class<?>> THRIFT_IFACE_MATCHER =
Matchers.subclassesOf(AnnotatedAuroraAdmin.class)
.and(Matchers.annotatedWith(DecoratedThrift.class));
@Override
protected void configure() {
// Layer ordering:
// APIVersion -> Log -> StatsExporter -> SchedulerThriftInterface
// It's important for this interceptor to be registered first to ensure it's at the 'top' of
// the stack and the standard message is always applied.
bindThriftDecorator(new ServerInfoInterceptor());
bindThriftDecorator(new LoggingInterceptor());
bindThriftDecorator(new ThriftStatsExporterInterceptor());
bindThriftDecorator(new ThrottlingInterceptor());
}
private void bindThriftDecorator(MethodInterceptor interceptor) {
bindThriftDecorator(binder(), THRIFT_IFACE_MATCHER, interceptor);
}
@VisibleForTesting
static void bindThriftDecorator(
Binder binder,
Matcher<? super Class<?>> classMatcher,
MethodInterceptor interceptor) {
binder.bindInterceptor(
classMatcher,
Matchers.returns(Matchers.subclassesOf(Response.class)),
interceptor);
binder.requestInjection(interceptor);
}
}