I did some more testing on this today. I tried changing out the c3p0
pooled connection for the org.apache.commons.dbcp.BasicDataSource class.
No change. The error trace in the browser leads me to believe it has
something to do with creating a TGT:
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
com.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
<more>
But my tickets are stored in memcache, not MySQL...
I'll keep digging, but any advice is appreciated!
Andy
On Mon, 11 Feb 2013, Andrew Morgan wrote:
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
--
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
