On Mon, 11 Feb 2013, Marvin Addison wrote: >> I used some iptables rules to simulate the MySQL server being unavailable. >> The following log entries appeared: >> >> 2013-01-23 16:09:34,309 ERROR >> [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] - The last packet >> successfully received from the server was 774,962,088 milliseconds ago. >> The last packet sent successfully to the server was 774,962,089 >> milliseconds ago. is longer than the server configured value of >> 'wait_timeout'. You should consider either expiring and/or testing >> connection validity before use in your application, increasing the server >> configured values for client timeouts, or using the Connector/J connection >> property 'autoReconnect=true' to avoid this problem. >> >> 2013-01-23 16:16:40,322 ERROR >> [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] - Could not create >> connection to database server. Attempted reconnect 3 times. Giving up. > > Are those the only errors? What exactly was the behavior of CAS from > the perspective of an end user? Did it emit a stack trace or simply > time out on a GET to /login? In any case I'm fairly surprised by this > behavior.
I just tested this against. I used iptables on the MySQL host to "DROP"
the packets destined for port 3306 from my test CAS server.
After applying this change, I loaded the CAS login page with no service
specified (worked) and then submitted my credentials. My web browser just
spins (10 minutes now) with no response received. I have attached the CAS
log file from this attempt as "cas-dev.log".
I tried again using iptables "REJECT", which sets "reject-with
icmp-port-unreachable". The same behavior occurs (browser spins). This
time, I let it go (actually, I went to a meeting). It appears that after
15 minutes it returned an error trace message in the browser:
{"failure":"true","exception.message":"org.springframework.webflow.execution.ActionExecutionException:
Exception thrown executing [AnnotatedAction@5021773d targetAction =
[EvaluateAction@451b6ee4 expression =
authenticationViaFormAction.submit(flowRequestContext,
flowScope.credentials, messageContext), resultExpression = [null]],
attributes = map[[empty]]] in state 'realSubmit' of flow 'login' -- action
execution attributes were
'map[[empty]]'","exception.stacktrace":"org.springframework.webflow.execution.ActionExecutionException:
Exception thrown executing [AnnotatedAction@5021773d targetAction =
[EvaluateAction@451b6ee4 expression =
authenticationViaFormAction.submit(flowRequestContext,
flowScope.credentials, messageContext), resultExpression = [null]],
attributes = map[[empty]]] in state 'realSubmit' of flow 'login' -- action
execution attributes were 'map[[empty]]'\n\tat
org.springframework.webflow.execution.ActionExecutor.execute(ActionExecutor.java:60)\n\tat
org.springframework.webflow.engine.ActionState.doEnter(ActionState.java:101)\n\tat
org.springframework.webflow.engine.State.enter(State.java:194)\n\tat
org.springframework.webflow.engine.Transition.execute(Transition.java:227)\n\tat
org.springframework.webflow.engine.impl.FlowExecutionImpl.execute(FlowExecutionImpl.java:393)\n\tat
org.springframework.webflow.engine.impl.RequestControlContextImpl.execute(RequestControlContextImpl.java:214)\n\tat
org.springframework.webflow.engine.TransitionableState.handleEvent(TransitionableState.java:119)\n\tat
org.springframework.webflow.engine.Flow.handleEvent(Flow.java:555)\n\tat
org.springframework.webflow.engine.impl.FlowExecutionImpl.handleEvent(FlowExecutionImpl.java:388)\n\tat
org.springframework.webflow.engine.impl.RequestControlContextImpl.handleEvent(RequestControlContextImpl.java:210)\n\tat
org.springframework.webflow.engine.ViewState.handleEvent(ViewState.java:232)\n\tat
org.springframework.webflow.engine.ViewState.resume(ViewState.java:196)\n\tat
org.springframework.webflow.engine.Flow.resume(Flow.java:545)\n\tat
org.springframework.webflow.engine.impl.FlowExecutionImpl.resume(FlowExecutionImpl.java:261)\n\tat
org.springframework.webflow.executor.FlowExecutorImpl.resumeExecution(FlowExecutorImpl.java:169)\n\tat
org.springframework.webflow.mvc.servlet.FlowHandlerAdapter.handle(FlowHandlerAdapter.java:183)\n\tat
org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:923)\n\tat
org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:852)\n\tat
org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:882)\n\tat
org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:789)\n\tat
javax.servlet.http.HttpServlet.service(HttpServlet.java:637)\n\tat
javax.servlet.http.HttpServlet.service(HttpServlet.java:717)\n\tat
org.jasig.cas.web.init.SafeDispatcherServlet.service_aroundBody2(SafeDispatcherServlet.java:128)\n\tat
org.jasig.cas.web.init.SafeDispatcherServlet.service_aroundBody3$advice(SafeDispatcherServlet.java:57)\n\tat
org.jasig.cas.web.init.SafeDispatcherServlet.service(SafeDispatcherServlet.java:1)\n\tat
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)\n\tat
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)\n\tat
org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88)\n\tat
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)\n\tat
org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:346)\n\tat
org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:259)\n\tat
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)\n\tat
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)\n\tat
com.github.inspektr.common.web.ClientInfoThreadLocalFilter.doFilter(ClientInfoThreadLocalFilter.java:63)\n\tat
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)\n\tat
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)\n\tat
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)\n\tat
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)\n\tat
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)\n\tat
com.googlecode.psiprobe.Tomcat60AgentValve.invoke(Tomcat60AgentValve.java:30)\n\tat
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)\n\tat
org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:615)\n\tat
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)\n\tat
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)\n\tat
org.apache.coyote.ajp.AjpAprProcessor.process(AjpAprProcessor.java:448)\n\tat
org.apache.coyote.ajp.AjpAprProtocol$AjpConnectionHandler.process(AjpAprProtocol.java:403)\n\tat
org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1703)\n\tat
java.lang.Thread.run(Thread.java:662)\nCaused by:
org.springframework.binding.expression.EvaluationException: An
OgnlException occurred getting the value for expression
'authenticationViaFormAction.submit(flowRequestContext,
flowScope.credentials, messageContext)' on context [class
org.springframework.webflow.engine.impl.RequestControlContextImpl]\n\tat
org.springframework.binding.expression.ognl.OgnlExpression.getValue(OgnlExpression.java:92)\n\tat
org.springframework.webflow.action.EvaluateAction.doExecute(EvaluateAction.java:75)\n\tat
org.springframework.webflow.action.AbstractAction.execute(AbstractAction.java:188)\n\tat
org.springframework.webflow.execution.AnnotatedAction.execute(AnnotatedAction.java:145)\n\tat
org.springframework.webflow.execution.ActionExecutor.execute(ActionExecutor.java:51)\n\t...
47 more\nCaused by: ognl.MethodFailedException: Method \"submit\" failed
for object org.jasig.cas.web.flow.AuthenticationViaFormAction@54c0ee9a
[org.springframework.transaction.CannotCreateTransactionException: Could
not open JPA EntityManager for transaction; nested exception is
javax.persistence.PersistenceException:
org.hibernate.TransactionException: JDBC begin transaction failed: ]\n\tat
ognl.OgnlRuntime.callAppropriateMethod(OgnlRuntime.java:1265)\n\tat
ognl.ObjectMethodAccessor.callMethod(ObjectMethodAccessor.java:68)\n\tat
ognl.OgnlRuntime.callMethod(OgnlRuntime.java:1329)\n\tat
ognl.ASTMethod.getValueBody(ASTMethod.java:90)\n\tat
ognl.SimpleNode.evaluateGetValueBody(SimpleNode.java:212)\n\tat
ognl.SimpleNode.getValue(SimpleNode.java:258)\n\tat
ognl.ASTChain.getValueBody(ASTChain.java:141)\n\tat
ognl.SimpleNode.evaluateGetValueBody(SimpleNode.java:212)\n\tat
ognl.SimpleNode.getValue(SimpleNode.java:258)\n\tat
ognl.Ognl.getValue(Ognl.java:494)\n\tat
org.springframework.binding.expression.ognl.OgnlExpression.getValue(OgnlExpression.java:85)\n\t...
51 more\nCaused by:
org.springframework.transaction.CannotCreateTransactionException: Could
not open JPA EntityManager for transaction; nested exception is
javax.persistence.PersistenceException:
org.hibernate.TransactionException: JDBC begin transaction failed: \n\tat
org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:427)\n\tat
org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:371)\n\tat
org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:335)\n\tat
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:105)\n\tat
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)\n\tat
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:90)\n\tat
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)\n\tat
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)\n\tat
sun.proxy.$Proxy41.createTicketGrantingTicket(Unknown Source)\n\tat
org.jasig.cas.web.flow.AuthenticationViaFormAction.submit_aroundBody2(AuthenticationViaFormAction.java:109)\n\tat
org.jasig.cas.web.flow.AuthenticationViaFormAction.submit_aroundBody3$advice(AuthenticationViaFormAction.java:57)\n\tat
org.jasig.cas.web.flow.AuthenticationViaFormAction.submit(AuthenticationViaFormAction.java:1)\n\tat
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)\n\tat
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)\n\tat
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)\n\tat
java.lang.reflect.Method.invoke(Method.java:597)\n\tat
ognl.OgnlRuntime.invokeMethod(OgnlRuntime.java:851)\n\tat
ognl.OgnlRuntime.callAppropriateMethod(OgnlRuntime.java:1253)\n\t... 61
more\nCaused by: javax.persistence.PersistenceException:
org.hibernate.TransactionException: JDBC begin transaction failed: \n\tat
org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1360)\n\tat
org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1288)\n\tat
org.hibernate.ejb.AbstractEntityManagerImpl.throwPersistenceException(AbstractEntityManagerImpl.java:1370)\n\tat
org.hibernate.ejb.TransactionImpl.begin(TransactionImpl.java:60)\n\tat
org.springframework.orm.jpa.DefaultJpaDialect.beginTransaction(DefaultJpaDialect.java:70)\n\tat
org.springframework.orm.jpa.vendor.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:59)\n\tat
org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:377)\n\t...
78 more\nCaused by: org.hibernate.TransactionException: JDBC begin
transaction failed: \n\tat
org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doBegin(JdbcTransaction.java:76)\n\tat
org.hibernate.engine.transaction.spi.AbstractTransactionImpl.begin(AbstractTransactionImpl.java:160)\n\tat
org.hibernate.internal.SessionImpl.beginTransaction(SessionImpl.java:1309)\n\tat
org.hibernate.ejb.TransactionImpl.begin(TransactionImpl.java:57)\n\t... 81
more\nCaused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException:
Communications link failure\n\nThe last packet successfully received from
the server was 965,644 milliseconds ago. The last packet sent
successfully to the server was 928,689 milliseconds ago.\n\tat
sun.reflect.GeneratedConstructorAccessor83.newInstance(Unknown
Source)\n\tat
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)\n\tat
java.lang.reflect.Constructor.newInstance(Constructor.java:513)\n\tat
com.mysql.jdbc.Util.handleNewInstance(Util.java:411)\n\tat
com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1117)\n\tat
com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3589)\n\tat
com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3478)\n\tat
com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4019)\n\tat
com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2490)\n\tat
com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2651)\n\tat
com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2728)\n\tat
com.mysql.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:5075)\n\tat
com.mchange.v2.c3p0.impl.NewProxyConnection.setAutoCommit(NewProxyConnection.java:881)\n\tat
org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doBegin(JdbcTransaction.java:72)\n\t...
84 more\nCaused by: java.net.SocketException: Connection refused\n\tat
java.net.SocketInputStream.socketRead0(Native Method)\n\tat
java.net.SocketInputStream.read(SocketInputStream.java:129)\n\tat
com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)\n\tat
com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)\n\tat
com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)\n\tat
com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3036)\n\tat
com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3489)\n\t... 92
more\n"}
Sorry for the painfully long paste.
For a final test, I change the iptables REJECT type to "reject-with
tcp-reset". With that setting, when I submit my credentials, I
immediately get an error trace message in the browser, and the CAS log
shows:
2013-02-11 15:52:34,932 ERROR
[org.hibernate.engine.jdbc.spi.SqlExceptionHelper] - Communications link failure
The last packet successfully received from the server was 105,609
milliseconds ago. The last packet sent successfully to the server was 1
milliseconds ago.
<more snipped>
>> Is there something wrong with my configuration?
>
> Not that I can see.
>
>> Is the wiki note about availability wrong?
>
> No. We've had database outages in the past and CAS has remained
> responsive. That jibes with the design and the wiki comment.
>
> Here's a theory: you've set up a firewall to swallow SYN (fairly
> typical firewall rule), which some component from database driver to
> c3p0 doesn't like it. In practice it's far more common to receive a
> RST packet when you attempt to communicate over a broken channel. If
> you've blackholed the MySQL port such that you get _nothing_ back from
> the other end, it's possible you're running into a weird edge case
> that's not handled well.
I think I have covered these cases in my testing above. Is there anything
else I should be trying or testing? Would more logs or debugging help
identify why CAS is hanging or dying when MySQL is unavailable? At least
with the RST mode, I can get results back pretty quickly!
Thanks a bunch Marvin.
Andy
--
You are currently subscribed to [email protected] as:
[email protected]
To unsubscribe, change settings or access archives, see
http://www.ja-sig.org/wiki/display/JSG/cas-user
cas-dev.log
Description: Binary data
