AW: crashing IdP db connection

John Morrison john.morrison at uadm.uu.se
Tue Apr 4 03:31:12 EDT 2017 

The database connection is fine, something goes wrong with the
IdP/tomcat pool connection towards the localhost connection to mariadb
when the users/app URL changes its already recorded CAS Session
corresponding to the initial CAS URL.

Caused by: javax.persistence.PersistenceException:
org.hibernate.HibernateException: identifier of an instance of
org.opensaml.storage.impl.JPAStorageRecord was altered from
69a3f9634b91ef06e65040b94b9f338918477c04fda037dbcc9f
df99c6174ee9:https://www.someurl.com/Default.aspx to
69a3f9634b91ef06e65040b94b9f338918477c04fda037dbcc9fdf99c6174ee9:https:
//www.someurl.com/default.aspx

This sets it in some sort of timeout, tomcat drops the db pool
connection due this error above.

The database is fine. No network issues. (localhost)

When stopping the tomcat when this happens, we get a shit load of logs
from tomcat, and takes quite some time to stop tomcat as seen below,
with only a few lines pasted here but this repeats for quite some time
until it eventually stops. 


03-Apr-2017 13:53:46.526 INFO [Thread-29]
org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
["ajp-nio-8009"]
03-Apr-2017 13:53:46.528 INFO [Thread-29]
org.apache.catalina.core.StandardService.stopInternal Stopping service
Catalina
03-Apr-2017 13:53:46.538 INFO [localhost-startStop-2]
org.apache.catalina.core.StandardWrapper.unload Waiting for 1
instance(s) to be deallocated for Servlet [idp]
03-Apr-2017 13:53:47.539 INFO [localhost-startStop-2]
org.apache.catalina.core.StandardWrapper.unload Waiting for 1
instance(s) to be deallocated for Servlet [idp]
03-Apr-2017 13:53:48.541 INFO [localhost-startStop-2]
org.apache.catalina.core.StandardWrapper.unload Waiting for 1
instance(s) to be deallocated for Servlet [idp]
03-Apr-2017 13:53:48.738 FINE [localhost-startStop-2]
org.apache.catalina.session.StandardManager.stopInternal Stopping
03-Apr-2017 13:53:48.738 FINE [localhost-startStop-2]
org.apache.catalina.session.StandardManager.doUnload Unloading persisted
sessions
03-Apr-2017 13:53:48.739 FINE [localhost-startStop-2]
org.apache.catalina.session.StandardManager.doUnload Saving persisted
sessions to SESSIONS.ser
03-Apr-2017 13:53:48.740 FINE [localhost-startStop-2]
org.apache.catalina.session.StandardManager.doUnload Unloading 22
sessions
03-Apr-2017 13:53:48.779 FINE [localhost-startStop-2]
org.apache.catalina.session.StandardManager.doUnload Expiring 22
persisted sessions
03-Apr-2017 13:53:48.780 FINE [localhost-startStop-2]
org.apache.catalina.session.StandardManager.doUnload Unloading complete
03-Apr-2017 13:53:53.600 WARNING [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesJdbc The
web application [idp] registered the JDBC driver
[org.mariadb.jdbc.Driver] but failed to unregister it when the web
application was stopped. To prevent a memory leak, the JDBC Driver has
been forcibly unregistered.
03-Apr-2017 13:53:53.601 WARNING [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads
The web application [idp] appears to have started a thread named
[MariaDb-timeout-1] but has failed to stop it. This is very likely to
create a memory leak. Stack trace of thread:
 sun.misc.Unsafe.park(Native Method)
 java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
 java.util.concurrent.locks.AbstractQueuedSynchronizer
$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
 java.util.concurrent.ScheduledThreadPoolExecutor
$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1081)
 java.util.concurrent.ScheduledThreadPoolExecutor
$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)

java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)

java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
 java.util.concurrent.ThreadPoolExecutor
$Worker.run(ThreadPoolExecutor.java:617)
 java.lang.Thread.run(Thread.java:745)
03-Apr-2017 13:53:53.605 WARNING [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads
The web application [idp] is still processing a request that has yet to
finish. This is very likely to create a memory leak. You can control the
time allowed for requests to finish by using the unloadDelay attribute
of the standard Context implementation. Stack trace of request
processing thread:

org.springframework.webflow.engine.support.DefaultTargetStateResolver.resolveTargetState(DefaultTargetStateResolver.java:58)

org.springframework.webflow.engine.Transition.execute(Transition.java:218)

org.springframework.webflow.engine.impl.FlowExecutionImpl.execute(FlowExecutionImpl.java:395)

org.springframework.webflow.engine.impl.RequestControlContextImpl.execute(RequestControlContextImpl.java:214)

org.springframework.webflow.engine.TransitionableState.handleEvent(TransitionableState.java:116)
 org.springframework.webflow.engine.Flow.handleEvent(Flow.java:547)

org.springframework.webflow.engine.impl.FlowExecutionImpl.handleEvent(FlowExecutionImpl.java:390)

org.springframework.webflow.engine.impl.RequestControlContextImpl.handleEvent(RequestControlContextImpl.java:210)

org.springframework.webflow.engine.ActionState.doEnter(ActionState.java:105)
 org.springframework.webflow.engine.State.enter(State.java:194)

org.springframework.webflow.engine.Transition.execute(Transition.java:228)

org.springframework.webflow.engine.impl.FlowExecutionImpl.execute(FlowExecutionImpl.java:395)

org.springframework.webflow.engine.impl.RequestControlContextImpl.execute(RequestControlContextImpl.java:214)

org.springframework.webflow.engine.support.TransitionExecutingFlowExecutionExceptionHandler.handle(TransitionExecutingFlowExecutionExceptionHandler.java:111)

org.springframework.webflow.engine.FlowExecutionExceptionHandlerSet.handleException(FlowExecutionExceptionHandlerSet.java:109)
 org.springframework.webflow.engine.Flow.handleException(Flow.java:600)

org.springframework.webflow.engine.impl.FlowExecutionImpl.tryFlowHandlers(FlowExecutionImpl.java:647)

org.springframework.webflow.engine.impl.FlowExecutionImpl.handleException(FlowExecutionImpl.java:603)

org.springframework.webflow.engine.impl.FlowExecutionImpl.handleException(FlowExecutionImpl.java:608)

org.springframework.webflow.engine.impl.FlowExecutionImpl.handleException(FlowExecutionImpl.java:608)

org.springframework.webflow.engine.impl.FlowExecutionImpl.handleException(FlowExecutionImpl.java:608)

org.springframework.webflow.engine.impl.FlowExecutionImpl.handleException(FlowExecutionImpl.java:608)

org.springframework.webflow.engine.impl.FlowExecutionImpl.handleException(FlowExecutionImpl.java:608)

org.springframework.webflow.engine.impl.FlowExecutionImpl.handleException(FlowExecutionImpl.java:608)

org.springframework.webflow.engine.impl.FlowExecutionImpl.handleException(FlowExecutionImpl.java:608)

org.springframework.webflow.engine.impl.FlowExecutionImpl.handleException(FlowExecutionImpl.java:608)

org.springframework.webflow.engine.impl.FlowExecutionImpl.handleException(FlowExecutionImpl.java:608)

org.springframework.webflow.engine.impl.FlowExecutionImpl.handleException(FlowExecutionImpl.java:608)

org.springframework.webflow.engine.impl.FlowExecutionImpl.handleException(FlowExecutionImpl.java:608)

org.springframework.webflow.engine.impl.FlowExecutionImpl.handleException(FlowExecutionImpl.java:608)

org.springframework.webflow.engine.impl.FlowExecutionImpl.handleException(FlowExecutionImpl.java:608)

org.springframework.webflow.engine.impl.FlowExecutionImpl.start(FlowExecutionImpl.java:225)

org.springframework.webflow.executor.FlowExecutorImpl.launchExecution(FlowExecutorImpl.java:140)

org.springframework.webflow.mvc.servlet.FlowHandlerAdapter.handle(FlowHandlerAdapter.java:263)

org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:963)

org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:897)

org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)

org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861)
 javax.servlet.http.HttpServlet.service(HttpServlet.java:622)

org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
 javax.servlet.http.HttpServlet.service(HttpServlet.java:729)

org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:291)

org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
 org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)

org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)

org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)

net.shibboleth.idp.log.SLF4JMDCServletFilter.doFilter(SLF4JMDCServletFilter.java:72)

org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)

org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)

net.shibboleth.utilities.java.support.net.RequestResponseContextFilter.doFilter(RequestResponseContextFilter.java:61)

org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)

org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)

org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197)

org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)

org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)

org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)

net.shibboleth.utilities.java.support.net.CookieBufferingFilter.doFilter(CookieBufferingFilter.java:68)

org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)

org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)

org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197)

org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)

org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:502)

org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:141)

org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)

org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:616)

org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)

org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:521)

org.apache.coyote.ajp.AbstractAjpProcessor.process(AbstractAjpProcessor.java:850)
 org.apache.coyote.AbstractProtocol
$AbstractConnectionHandler.process(AbstractProtocol.java:674)
 org.apache.tomcat.util.net.NioEndpoint
$SocketProcessor.doRun(NioEndpoint.java:1500)
 org.apache.tomcat.util.net.NioEndpoint
$SocketProcessor.run(NioEndpoint.java:1456)

java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
 java.util.concurrent.ThreadPoolExecutor
$Worker.run(ThreadPoolExecutor.java:617)
 org.apache.tomcat.util.threads.TaskThread
$WrappingRunnable.run(TaskThread.java:61)
 java.lang.Thread.run(Thread.java:745)
03-Apr-2017 13:53:53.606 WARNING [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads
The web application [idp] appears to have started a thread named
[Thread-32] but has failed to stop it. This is very likely to create a
memory leak. Stack trace of thread:
 java.net.SocketInputStream.socketRead0(Native Method)
 java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
 java.net.SocketInputStream.read(SocketInputStream.java:171)
 java.net.SocketInputStream.read(SocketInputStream.java:141)
 sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
 sun.security.ssl.InputRecord.read(InputRecord.java:503)
 sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:973)
 sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:930)
 sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
 java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
 java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
 java.io.BufferedInputStream.read(BufferedInputStream.java:345)
 com.sun.jndi.ldap.Connection.run(Connection.java:860)
 java.lang.Thread.run(Thread.java:745)
03-Apr-2017 13:53:53.606 WARNING [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads
The web application [idp] appears to have started a thread named
[Thread-33] but has failed to stop it. This is very likely to create a
memory leak. Stack trace of thread:
 java.net.SocketInputStream.socketRead0(Native Method)
 java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
 java.net.SocketInputStream.read(SocketInputStream.java:171)
 java.net.SocketInputStream.read(SocketInputStream.java:141)
 sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
 sun.security.ssl.InputRecord.read(InputRecord.java:503)
 sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:973)
 sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:930)
 sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
 java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
 java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
 java.io.BufferedInputStream.read(BufferedInputStream.java:345)
 com.sun.jndi.ldap.Connection.run(Connection.java:860)
 java.lang.Thread.run(Thread.java:745)
03-Apr-2017 13:53:53.606 WARNING [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads
The web application [idp] appears to have started a thread named
[Thread-34] but has failed to stop it. This is very likely to create a
memory leak. Stack trace of thread:
 java.net.SocketInputStream.socketRead0(Native Method)
 java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
 java.net.SocketInputStream.read(SocketInputStream.java:171)
 java.net.SocketInputStream.read(SocketInputStream.java:141)
 sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
 sun.security.ssl.InputRecord.read(InputRecord.java:503)
 sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:973)
 sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:930)
 sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
 java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
 java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
 java.io.BufferedInputStream.read(BufferedInputStream.java:345)
 com.sun.jndi.ldap.Connection.run(Connection.java:860)
 java.lang.Thread.run(Thread.java:745)
03-Apr-2017 13:53:53.607 WARNING [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads
The web application [idp] appears to have started a thread named
[Thread-35] but has failed to stop it. This is very likely to create a
memory leak. Stack trace of thread:
 sun.misc.Unsafe.park(Native Method)
 java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
 java.util.concurrent.locks.AbstractQueuedSynchronizer
$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
 java.util.concurrent.ScheduledThreadPoolExecutor
$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
 java.util.concurrent.ScheduledThreadPoolExecutor
$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)


java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
 java.util.concurrent.ThreadPoolExecutor
$Worker.run(ThreadPoolExecutor.java:617)
 java.lang.Thread.run(Thread.java:745)
03-Apr-2017 13:53:53.611 SEVERE [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [idp] created a ThreadLocal with key of type [org.ldaptive.ssl.ThreadLocalTLSSocketFactory.ThreadLocalSslConfig] (value [org.ldaptive.ssl.ThreadLocalTLSSocketFactory$ThreadLocalSslConfig at 21ad8b94]) and a value of type [org.ldaptive.ssl.SslConfig] (value [[org.ldaptive.ssl.SslConfig at 255373547::credentialConfig=org.ldaptive.ssl.CredentialConfigFactory$2 at 1dd28e3e, trustManagers=[[org.ldaptive.ssl.HostnameVerifyingTrustManager at 2068140682::hostnameVerifier=org.ldaptive.ssl.DefaultHostnameVerifier at 29473862, hostnames=[akkatest-ldap.its.uu.se]]], enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.
03-Apr-2017 13:53:53.612 SEVERE [localhost-startStop-2]
org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [idp] created a ThreadLocal with key of type [org.ldaptive.ssl.ThreadLocalTLSSocketFactory.ThreadLocalSslConfig] (value [org.ldaptive.ssl.ThreadLocalTLSSocketFactory$ThreadLocalSslConfig at 21ad8b94]) and a value of type [org.ldaptive.ssl.SslConfig] (value [[org.ldaptive.ssl.SslConfig at 82434137::credentialConfig=org.ldaptive.ssl.CredentialConfigFactory$2 at 1dd28e3e, trustManagers=[[org.ldaptive.ssl.HostnameVerifyingTrustManager at 1612162494::hostnameVerifier=org.ldaptive.ssl.DefaultHostnameVerifier at 1cb0e702, hostnames=[akkatest-ldap.its.uu.se]]], enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null]]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.



here is a debug of when it happens:



2017-04-03 14:14:08,044 - DEBUG
[net.shibboleth.idp.cas.flow.impl.UpdateIdPSessionWithSPSessionAction:104] - Created SP session CASSPSession: https://some.url.com/default.aspx via ST-1491221647328-xdMgzOYDtI914Jl4MuXLKgcH2
2017-04-03 14:14:08,044 - DEBUG
[net.shibboleth.idp.session.impl.StorageBackedIdPSession:664] - Saving
SPSession for service https://some.url.com/default.aspx in session
3d2016a122e988749953ef726f5f4b1b22016efa9d337e1e1401d04e46c35233
2017-04-03 14:14:08,049 - DEBUG
[net.shibboleth.idp.session.SPSessionSerializerRegistry:86] - Registry
located StorageSerializer of type
'net.shibboleth.idp.cas.session.impl.CASSPSessionSerializer' for
SPSession type 'class net.shibboleth
.idp.cas.session.impl.CASSPSession'
2017-04-03 14:14:08,050 - DEBUG
[org.hibernate.engine.jdbc.internal.LogicalConnectionImpl:226] -
Obtaining JDBC connection
2017-04-03 14:14:08,050 - DEBUG
[org.hibernate.engine.jdbc.internal.LogicalConnectionImpl:232] -
Obtained JDBC connection
2017-04-03 14:14:08,051 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:371] -
Registering statement [HikariProxyPreparedStatement at 569621193 wrapping
sql : 'select jpastorage0_.context as context1_0_0_, jpastorage0_.id as 
id2_0_0_, jpastorage0_.expires as expires3_0_0_, jpastorage0_.value as
value4_0_0_, jpastorage0_.version as version5_0_0_ from StorageRecords
jpastorage0_ where jpastorage0_.context=? and jpastorage0_.id=? for
update', parameters : [null,
null]]
2017-04-03 14:14:08,051 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:386] -
Registering last query statement [HikariProxyPreparedStatement at 569621193
wrapping sql : 'select jpastorage0_.context as context1_0_0_, jpastora
ge0_.id as id2_0_0_, jpastorage0_.expires as expires3_0_0_,
jpastorage0_.value as value4_0_0_, jpastorage0_.version as version5_0_0_
from StorageRecords jpastorage0_ where jpastorage0_.context=? and
jpastorage0_.id=? for update', paramete
rs : [null,null]]
2017-04-03 14:14:08,052 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:437] -
Registering result set [HikariProxyResultSet at 1053041677 wrapping
org.mariadb.jdbc.internal.queryresults.resultset.MariaSelectResultSet at 79f9b5a7
]
2017-04-03 14:14:08,053 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:455] - Releasing
result set [HikariProxyResultSet at 1053041677 wrapping
org.mariadb.jdbc.internal.queryresults.resultset.MariaSelectResultSet at 79f9b5a7]
2017-04-03 14:14:08,053 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:573] - Closing
result set [HikariProxyResultSet at 1053041677 wrapping
org.mariadb.jdbc.internal.queryresults.resultset.MariaSelectResultSet at 79f9b5a7]
2017-04-03 14:14:08,053 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:412] - Releasing
statement [HikariProxyPreparedStatement at 569621193 wrapping sql : 'select
jpastorage0_.context as context1_0_0_, jpastorage0_.id as id
2_0_0_, jpastorage0_.expires as expires3_0_0_, jpastorage0_.value as
value4_0_0_, jpastorage0_.version as version5_0_0_ from StorageRecords
jpastorage0_ where jpastorage0_.context=? and jpastorage0_.id=? for
update', parameters : ['3d2016
a122e988749953ef726f5f4b1b22016efa9d337e1e1401d04e46c35233','https://some.url.com/default.aspx']]
2017-04-03 14:14:08,053 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:525] - Closing
prepared statement [HikariProxyPreparedStatement at 569621193 wrapping
sql : 'select jpastorage0_.context as context1_0_0_, jpastorage0_.i
d as id2_0_0_, jpastorage0_.expires as expires3_0_0_, jpastorage0_.value
as value4_0_0_, jpastorage0_.version as version5_0_0_ from
StorageRecords jpastorage0_ where jpastorage0_.context=? and
jpastorage0_.id=? for update', parameters : [
'3d2016a122e988749953ef726f5f4b1b22016efa9d337e1e1401d04e46c35233','https://some.url.com/default.aspx']]
2017-04-03 14:14:08,054 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:278] - Starting
after statement execution processing [ON_CLOSE]
2017-04-03 14:14:08,054 - DEBUG
[org.opensaml.storage.impl.JPAStorageService:140] - Duplicate record
'https://some.url.com/default.aspx' in context
'3d2016a122e988749953ef726f5f4b1b22016efa9d337e1e1401d04e46c35233'
2017-04-03 14:14:08,076 - ERROR
[org.opensaml.storage.impl.JPAStorageService:188] - Error committing
transaction
javax.persistence.RollbackException: Error while committing the
transaction
        at
org.hibernate.jpa.internal.TransactionImpl.commit(TransactionImpl.java:94)
Caused by: javax.persistence.PersistenceException:
org.hibernate.HibernateException: identifier of an instance of
org.opensaml.storage.impl.JPAStorageRecord was altered from
3d2016a122e988749953ef726f5f4b1b22016efa9d337e1e1401d04e46c35233
:https://some.url.com/default.aspx to
3d2016a122e988749953ef726f5f4b1b22016efa9d337e1e1401d04e46c35233:https://some.url.com/Default.aspx
        at
org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1763)
Caused by: org.hibernate.HibernateException: identifier of an instance
of org.opensaml.storage.impl.JPAStorageRecord was altered from
3d2016a122e988749953ef726f5f4b1b22016efa9d337e1e1401d04e46c35233:https://some.url.com/default.aspx to 3d
2016a122e988749953ef726f5f4b1b22016efa9d337e1e1401d04e46c35233:https://some.url.com/Default.aspx
        at
org.hibernate.event.internal.DefaultFlushEntityEventListener.checkId(DefaultFlushEntityEventListener.java:80)
2017-04-03 14:14:08,077 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:199] - Closing
JDBC container
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl at 11f6682f]
2017-04-03 14:14:08,078 - TRACE
[org.hibernate.engine.jdbc.internal.LogicalConnectionImpl:178] - Closing
logical connection
2017-04-03 14:14:08,078 - DEBUG
[org.hibernate.engine.jdbc.internal.LogicalConnectionImpl:246] -
Releasing JDBC connection
2017-04-03 14:14:08,078 - DEBUG
[org.hibernate.engine.jdbc.internal.LogicalConnectionImpl:264] -
Released JDBC connection
2017-04-03 14:14:08,078 - TRACE
[org.hibernate.engine.jdbc.internal.LogicalConnectionImpl:190] - Logical
connection closed
2017-04-03 14:14:08,079 - DEBUG
[org.hibernate.engine.jdbc.internal.LogicalConnectionImpl:226] -
Obtaining JDBC connection
2017-04-03 14:14:08,079 - DEBUG
[org.hibernate.engine.jdbc.internal.LogicalConnectionImpl:232] -
Obtained JDBC connection
2017-04-03 14:14:08,079 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:371] -
Registering statement [HikariProxyPreparedStatement at 2128666784 wrapping
sql : 'select jpastorage0_.context as context1_0_0_, jpastorage0_.id as
 id2_0_0_, jpastorage0_.expires as expires3_0_0_, jpastorage0_.value as
value4_0_0_, jpastorage0_.version as version5_0_0_ from StorageRecords
jpastorage0_ where jpastorage0_.context=? and jpastorage0_.id=? for
update', parameters : [null
,null]]
2017-04-03 14:14:08,080 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:386] -
Registering last query statement
[HikariProxyPreparedStatement at 2128666784 wrapping sql : 'select
jpastorage0_.context as context1_0_0_, jpastor
age0_.id as id2_0_0_, jpastorage0_.expires as expires3_0_0_,
jpastorage0_.value as value4_0_0_, jpastorage0_.version as version5_0_0_
from StorageRecords jpastorage0_ where jpastorage0_.context=? and
jpastorage0_.id=? for update', paramet
ers : [null,null]]
2017-04-03 14:14:08,085 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:437] -
Registering result set [HikariProxyResultSet at 331598516 wrapping
org.mariadb.jdbc.internal.queryresults.resultset.MariaSelectResultSet at 70cf84b6]
2017-04-03 14:14:08,086 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:455] - Releasing
result set [HikariProxyResultSet at 331598516 wrapping
org.mariadb.jdbc.internal.queryresults.resultset.MariaSelectResultSet at 70cf84b6]
2017-04-03 14:14:08,086 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:573] - Closing
result set [HikariProxyResultSet at 331598516 wrapping
org.mariadb.jdbc.internal.queryresults.resultset.MariaSelectResultSet at 70cf84b6]
2017-04-03 14:14:08,087 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:412] - Releasing
statement [HikariProxyPreparedStatement at 2128666784 wrapping sql :
'select jpastorage0_.context as context1_0_0_, jpastorage0_.id as i
d2_0_0_, jpastorage0_.expires as expires3_0_0_, jpastorage0_.value as
value4_0_0_, jpastorage0_.version as version5_0_0_ from StorageRecords
jpastorage0_ where jpastorage0_.context=? and jpastorage0_.id=? for
update', parameters : ['3d201
6a122e988749953ef726f5f4b1b22016efa9d337e1e1401d04e46c35233','https://some.url.com/default.aspx']]
2017-04-03 14:14:08,087 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:525] - Closing
prepared statement [HikariProxyPreparedStatement at 2128666784 wrapping
sql : 'select jpastorage0_.context as context1_0_0_, jpastorage0_.
id as id2_0_0_, jpastorage0_.expires as expires3_0_0_,
jpastorage0_.value as value4_0_0_, jpastorage0_.version as version5_0_0_
from StorageRecords jpastorage0_ where jpastorage0_.context=? and
jpastorage0_.id=? for update', parameters : 
['3d2016a122e988749953ef726f5f4b1b22016efa9d337e1e1401d04e46c35233','https://some.url.com/default.aspx']]
2017-04-03 14:14:08,087 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:278] - Starting
after statement execution processing [ON_CLOSE]
2017-04-03 14:14:08,089 - DEBUG
[org.hibernate.engine.jdbc.internal.LogicalConnectionImpl:226] -
Obtaining JDBC connection
2017-04-03 14:14:08,090 - DEBUG
[org.hibernate.engine.jdbc.internal.LogicalConnectionImpl:232] -
Obtained JDBC connection
2017-04-03 14:14:08,101 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:371] -
Registering statement [HikariProxyPreparedStatement at 697175822 wrapping
sql : 'select jpastorage0_.context as context1_0_0_, jpastorage0_.id as 
id2_0_0_, jpastorage0_.expires as expires3_0_0_, jpastorage0_.value as
value4_0_0_, jpastorage0_.version as version5_0_0_ from StorageRecords
jpastorage0_ where jpastorage0_.context=? and jpastorage0_.id=? for
update', parameters : [null,
null]]
2017-04-03 14:14:08,101 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:386] -
Registering last query statement [HikariProxyPreparedStatement at 697175822
wrapping sql : 'select jpastorage0_.context as context1_0_0_, jpastora
ge0_.id as id2_0_0_, jpastorage0_.expires as expires3_0_0_,
jpastorage0_.value as value4_0_0_, jpastorage0_.version as version5_0_0_
from StorageRecords jpastorage0_ where jpastorage0_.context=? and
jpastorage0_.id=? for update', paramete
rs : [null,null]]
2017-04-03 14:14:08,102 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:437] -
Registering result set [HikariProxyResultSet at 868623070 wrapping
org.mariadb.jdbc.internal.queryresults.resultset.MariaSelectResultSet at 7b0a1328]
2017-04-03 14:14:08,103 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:455] - Releasing
result set [HikariProxyResultSet at 868623070 wrapping
org.mariadb.jdbc.internal.queryresults.resultset.MariaSelectResultSet at 7b0a1328]
2017-04-03 14:14:08,103 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:573] - Closing
result set [HikariProxyResultSet at 868623070 wrapping
org.mariadb.jdbc.internal.queryresults.resultset.MariaSelectResultSet at 7b0a1328]
2017-04-03 14:14:08,103 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:412] - Releasing
statement [HikariProxyPreparedStatement at 697175822 wrapping sql : 'select
jpastorage0_.context as context1_0_0_, jpastorage0_.id as id
2_0_0_, jpastorage0_.expires as expires3_0_0_, jpastorage0_.value as
value4_0_0_, jpastorage0_.version as version5_0_0_ from StorageRecords
jpastorage0_ where jpastorage0_.context=? and jpastorage0_.id=? for
update', parameters : ['3d2016
a122e988749953ef726f5f4b1b22016efa9d337e1e1401d04e46c35233','https://some.url.com/default.aspx']]
2017-04-03 14:14:08,104 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:525] - Closing
prepared statement [HikariProxyPreparedStatement at 697175822 wrapping
sql : 'select jpastorage0_.context as context1_0_0_, jpastorage0_.i
d as id2_0_0_, jpastorage0_.expires as expires3_0_0_, jpastorage0_.value
as value4_0_0_, jpastorage0_.version as version5_0_0_ from
StorageRecords jpastorage0_ where jpastorage0_.context=? and
jpastorage0_.id=? for update', parameters : [
'3d2016a122e988749953ef726f5f4b1b22016efa9d337e1e1401d04e46c35233','https://some.url.com/default.aspx']]
2017-04-03 14:14:08,104 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:278] - Starting
after statement execution processing [ON_CLOSE]
2017-04-03 14:14:08,105 - DEBUG
[org.hibernate.engine.jdbc.internal.LogicalConnectionImpl:226] -
Obtaining JDBC connection
2017-04-03 14:14:08,106 - DEBUG
[org.hibernate.engine.jdbc.internal.LogicalConnectionImpl:232] -
Obtained JDBC connection
2017-04-03 14:14:08,107 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:371] -
Registering statement [HikariProxyPreparedStatement at 1348928964 wrapping
sql : 'select jpastorage0_.context as context1_0_0_, jpastorage0_.id as
 id2_0_0_, jpastorage0_.expires as expires3_0_0_, jpastorage0_.value as
value4_0_0_, jpastorage0_.version as version5_0_0_ from StorageRecords
jpastorage0_ where jpastorage0_.context=? and jpastorage0_.id=? for
update', parameters : [null
,null]]
2017-04-03 14:14:08,108 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:386] -
Registering last query statement
[HikariProxyPreparedStatement at 1348928964 wrapping sql : 'select
jpastorage0_.context as context1_0_0_, jpastor
age0_.id as id2_0_0_, jpastorage0_.expires as expires3_0_0_,
jpastorage0_.value as value4_0_0_, jpastorage0_.version as version5_0_0_
from StorageRecords jpastorage0_ where jpastorage0_.context=? and
jpastorage0_.id=? for update', paramet
ers : [null,null]]
2017-04-03 14:14:08,108 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:437] -
Registering result set [HikariProxyResultSet at 1379208644 wrapping
org.mariadb.jdbc.internal.queryresults.resultset.MariaSelectResultSet at 790dd7f9
]
2017-04-03 14:14:08,109 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:455] - Releasing
result set [HikariProxyResultSet at 1379208644 wrapping
org.mariadb.jdbc.internal.queryresults.resultset.MariaSelectResultSet at 790dd7f9]
2017-04-03 14:14:08,109 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:573] - Closing
result set [HikariProxyResultSet at 1379208644 wrapping
org.mariadb.jdbc.internal.queryresults.resultset.MariaSelectResultSet at 790dd7f9]
2017-04-03 14:14:08,110 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:412] - Releasing
statement [HikariProxyPreparedStatement at 1348928964 wrapping sql :
'select jpastorage0_.context as context1_0_0_, jpastorage0_.id as i
d2_0_0_, jpastorage0_.expires as expires3_0_0_, jpastorage0_.value as
value4_0_0_, jpastorage0_.version as version5_0_0_ from StorageRecords
jpastorage0_ where jpastorage0_.context=? and jpastorage0_.id=? for
update', parameters : ['3d201
6a122e988749953ef726f5f4b1b22016efa9d337e1e1401d04e46c35233','https://some.url.com/default.aspx']]
2017-04-03 14:14:08,110 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:525] - Closing
prepared statement [HikariProxyPreparedStatement at 1348928964 wrapping
sql : 'select jpastorage0_.context as context1_0_0_, jpastorage0_.
id as id2_0_0_, jpastorage0_.expires as expires3_0_0_,
jpastorage0_.value as value4_0_0_, jpastorage0_.version as version5_0_0_
from StorageRecords jpastorage0_ where jpastorage0_.context=? and
jpastorage0_.id=? for update', parameters : 
['3d2016a122e988749953ef726f5f4b1b22016efa9d337e1e1401d04e46c35233','https://some.url.com/default.aspx']]
2017-04-03 14:14:08,111 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:278] - Starting
after statement execution processing [ON_CLOSE]
2017-04-03 14:14:08,120 - DEBUG
[org.hibernate.engine.jdbc.internal.LogicalConnectionImpl:226] -
Obtaining JDBC connection
2017-04-03 14:14:08,121 - DEBUG
[org.hibernate.engine.jdbc.internal.LogicalConnectionImpl:232] -
Obtained JDBC connection
2017-04-03 14:14:08,124 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:371] -
Registering statement [HikariProxyPreparedStatement at 1409494078 wrapping
sql : 'select jpastorage0_.context as context1_0_0_, jpastorage0_.id as
 id2_0_0_, jpastorage0_.expires as expires3_0_0_, jpastorage0_.value as
value4_0_0_, jpastorage0_.version as version5_0_0_ from StorageRecords
jpastorage0_ where jpastorage0_.context=? and jpastorage0_.id=? for
update', parameters : [null
,null]]
2017-04-03 14:14:08,124 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:386] -
Registering last query statement
[HikariProxyPreparedStatement at 1409494078 wrapping sql : 'select
jpastorage0_.context as context1_0_0_, jpastor
age0_.id as id2_0_0_, jpastorage0_.expires as expires3_0_0_,
jpastorage0_.value as value4_0_0_, jpastorage0_.version as version5_0_0_
from StorageRecords jpastorage0_ where jpastorage0_.context=? and
jpastorage0_.id=? for update', paramet
ers : [null,null]]
2017-04-03 14:14:08,125 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:437] -
Registering result set [HikariProxyResultSet at 1745275126 wrapping
org.mariadb.jdbc.internal.queryresults.resultset.MariaSelectResultSet at d35a684]
2017-04-03 14:14:08,126 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:455] - Releasing
result set [HikariProxyResultSet at 1745275126 wrapping
org.mariadb.jdbc.internal.queryresults.resultset.MariaSelectResultSet at d35a684]
2017-04-03 14:14:08,126 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:573] - Closing
result set [HikariProxyResultSet at 1745275126 wrapping
org.mariadb.jdbc.internal.queryresults.resultset.MariaSelectResultSet at d35a684]
2017-04-03 14:14:08,127 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:412] - Releasing
statement [HikariProxyPreparedStatement at 1409494078 wrapping sql :
'select jpastorage0_.context as context1_0_0_, jpastorage0_.id as i
d2_0_0_, jpastorage0_.expires as expires3_0_0_, jpastorage0_.value as
value4_0_0_, jpastorage0_.version as version5_0_0_ from StorageRecords
jpastorage0_ where jpastorage0_.context=? and jpastorage0_.id=? for
update', parameters : ['3d201
6a122e988749953ef726f5f4b1b22016efa9d337e1e1401d04e46c35233','https://some.url.com/default.aspx']]
2017-04-03 14:14:08,127 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:525] - Closing
prepared statement [HikariProxyPreparedStatement at 1409494078 wrapping
sql : 'select jpastorage0_.context as context1_0_0_, jpastorage0_.
id as id2_0_0_, jpastorage0_.expires as expires3_0_0_,
jpastorage0_.value as value4_0_0_, jpastorage0_.version as version5_0_0_
from StorageRecords jpastorage0_ where jpastorage0_.context=? and
jpastorage0_.id=? for update', parameters : 
['3d2016a122e988749953ef726f5f4b1b22016efa9d337e1e1401d04e46c35233','https://some.url.com/default.aspx']]
2017-04-03 14:14:08,127 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:278] - Starting
after statement execution processing [ON_CLOSE]
2017-04-03 14:14:08,128 - TRACE
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl:199] - Closing
JDBC container
[org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl at 10f50821]
2017-04-03 14:14:08,128 - TRACE
[org.hibernate.engine.jdbc.internal.LogicalConnectionImpl:178] - Closing
logical connection
2017-04-03 14:14:08,128 - DEBUG
[org.hibernate.engine.jdbc.internal.LogicalConnectionImpl:246] -
Releasing JDBC connection
2017-04-03 14:14:08,129 - DEBUG
[org.hibernate.engine.jdbc.internal.LogicalConnectionImpl:264] -
Released JDBC connection
2017-04-03 14:14:08,129 - TRACE
[org.hibernate.engine.jdbc.internal.LogicalConnectionImpl:190] - Logical
connection closed
2017-04-03 14:14:08,141 - ERROR [net.shibboleth.idp.cas:-2] - Uncaught
runtime exception
javax.persistence.RollbackException: Error while committing the
transaction
        at
org.hibernate.jpa.internal.TransactionImpl.commit(TransactionImpl.java:94)
Caused by: javax.persistence.PersistenceException:
org.hibernate.HibernateException: identifier of an instance of
org.opensaml.storage.impl.JPAStorageRecord was altered from
3d2016a122e988749953ef726f5f4b1b22016efa9d337e1e1401d04e46c35233
:https://some.url.com/default.aspx to
3d2016a122e988749953ef726f5f4b1b22016efa9d337e1e1401d04e46c35233:https://some.url.com/Default.aspx
        at
org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1763)
Caused by: org.hibernate.HibernateException: identifier of an instance
of org.opensaml.storage.impl.JPAStorageRecord was altered from
3d2016a122e988749953ef726f5f4b1b22016efa9d337e1e1401d04e46c35233:https://some.url.com/default.aspx to 3d
2016a122e988749953ef726f5f4b1b22016efa9d337e1e1401d04e46c35233:https://some.url.com/Default.aspx
        at
org.hibernate.event.internal.DefaultFlushEntityEventListener.checkId(DefaultFlushEntityEventListener.java:80)
2017-04-03 14:14:08,180 - WARN
[org.opensaml.profile.action.impl.LogEvent:105] - A non-proceed event
occurred while processing the request: RuntimeException
2017-04-03 14:14:08,185 - INFO [Shibboleth-Audit.SSO:241] -
20170403T121408Z|||https://some.url.com/default.aspx|
https://www.apereo.org/cas/protocol/servi

More information about the users mailing list