Too long conversations between IDP and SP

Tue Sep 8 10:52:10 EDT 2015

Dear Commnunity,

I am running a single IDP 3.1.1 on Debian Jessie, Tomcat 7:

### Operating Environment Information
operating_system: Linux
operating_system_version: 3.16.0-4-amd64
operating_system_architecture: amd64
jdk_version: 1.7.0_79
available_cores: 2
used_memory: 553 MB
maximum_memory: 592 MB

### Identity Provider Information
idp_version: 3.1.1

Users encounter from time to time log responses between authentication and connection to the SP. The idp-process.log shows series of succeeded authentication, ERROR, and series of audit:

2015-09-08 09:40:58,994 - INFO [org.ldaptive.auth.Authenticator:259] - Authentication succeeded for dn: user1
2015-09-08 09:41:05,936 - INFO [org.ldaptive.auth.Authenticator:259] - Authentication succeeded for dn: user2
2015-09-08 09:41:08,192 - ERROR [org.opensaml.profile.action.impl.DecodeMessage:73] - Profile Action DecodeMessage: Unable to decode incoming request
2015-09-08 09:41:22,917 - INFO [org.ldaptive.auth.Authenticator:259] - Authentication succeeded for dn: user3
2015-09-08 09:41:25,826 - INFO [org.ldaptive.auth.Authenticator:259] - Authentication succeeded for dn: user4
2015-09-08 09:41:26,072 - INFO [org.ldaptive.auth.Authenticator:259] - Authentication failed for dn: user5
2015-09-08 09:41:30,434 - INFO [org.ldaptive.auth.Authenticator:259] - Authentication failed for dn: user5
2015-09-08 09:41:34,637 - INFO [org.ldaptive.auth.Authenticator:259] - Authentication succeeded for dn: user6
2015-09-08 09:41:37,336 - ERROR [org.springframework.webflow.conversation.impl.LockTimeoutException:76] -
2015-09-08 09:41:38,705 - INFO [org.ldaptive.auth.Authenticator:259] - Authentication succeeded for dn: user5
2015-09-08 09:41:40,794 - INFO [org.ldaptive.auth.Authenticator:259] - Authentication succeeded for dn: user7
2015-09-08 09:41:43,278 - INFO [org.ldaptive.auth.Authenticator:259] - Authentication succeeded for dn: user8
2015-09-08 09:41:43,336 - INFO [org.ldaptive.auth.Authenticator:259] - Authentication succeeded for dn: user9
2015-09-08 09:41:45,687 - INFO [org.ldaptive.auth.Authenticator:259] - Authentication succeeded for dn: user10
2015-09-08 09:41:48,175 - ERROR [org.springframework.webflow.conversation.impl.LockTimeoutException:76] -
2015-09-08 09:41:49,847 - INFO [Shibboleth-Audit.SSO:241] - 20150908T074149Z|https://www.unifr.ch/shibboleth|user2
2015-09-08 09:41:49,889 - INFO [Shibboleth-Audit.SSO:241] - 20150908T074149Z|https://moodle2.unifr.ch/shibboleth|user6
2015-09-08 09:41:49,877 - INFO [Shibboleth-Audit.SSO:241] - 20150908T074149Z|https://www.unifr.ch/shibboleth|user3
2015-09-08 09:41:49,892 - INFO [Shibboleth-Audit.SSO:241] - 20150908T074149Z|https://bgershop.staempfli.com/shibboleth|user10
2015-09-08 09:41:49,898 - INFO [Shibboleth-Audit.SSO:241] - 20150908T074149Z|https://moodle2.unifr.ch/shibboleth|user7
2015-09-08 09:41:49,901 - INFO [Shibboleth-Audit.SSO:241] - 20150908T074149Z|https://moodle2.unifr.ch/shibboleth|user4
2015-09-08 09:41:49,913 - INFO [Shibboleth-Audit.SSO:241] - 20150908T074149Z|https://moodle2.unifr.ch/shibboleth|user9
2015-09-08 09:41:49,916 - INFO [Shibboleth-Audit.SSO:241] - 20150908T074149Z|https://moodle2.unifr.ch/shibboleth|user1
2015-09-08 09:41:49,918 - INFO [Shibboleth-Audit.SSO:241] - 20150908T074149Z|https://www.unifr.ch/shibboleth|user5
2015-09-08 09:41:49,925 - INFO [Shibboleth-Audit.SSO:241] - 20150908T074149Z|https://www.unifr.ch/shibboleth|user8

The idp server is not loaded.

Details of the ERROR LockTimeoutException:76:

2015-09-08 09:50:46,398 - ERROR [org.springframework.webflow.conversation.impl.LockTimeoutException:76] -
org.springframework.webflow.conversation.impl.LockTimeoutException: Unable to acquire conversation lock after 30 seconds
                at org.springframework.webflow.conversation.impl.JdkConcurrentConversationLock.lock(JdkConcurrentConversationLock.java:44)
2015-09-08 09:50:53,129 - ERROR [org.springframework.webflow.conversation.impl.LockTimeoutException:76] -
org.springframework.webflow.conversation.impl.LockTimeoutException: Unable to acquire conversation lock after 30 seconds
                at org.springframework.webflow.conversation.impl.JdkConcurrentConversationLock.lock(JdkConcurrentConversationLock.java:44)
2015-09-08 09:50:54,340 - ERROR [net.shibboleth.idp.profile.impl.ResolveAttributes:256] - Profile Action ResolveAttributes: Error resolving attributes
net.shibboleth.idp.attribute.resolver.ResolutionException: org.opensaml.saml.common.SAMLException: ID storage error retrieving persistent identifier
                at net.shibboleth.idp.saml.attribute.resolver.impl.StoredIDDataConnector.doDataConnectorResolve(StoredIDDataConnector.java:167)
Caused by: org.opensaml.saml.common.SAMLException: ID storage error retrieving persistent identifier
                at net.shibboleth.idp.saml.nameid.impl.StoredPersistentIdGenerationStrategy.generate(StoredPersistentIdGenerationStrategy.java:126)
Caused by: java.io.IOException: org.apache.commons.dbcp.SQLNestedException: Cannot get a connection, pool error Timeout waiting for idle object
                at net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore.getActiveEntry(JDBCPersistentIdStore.java:415)
Caused by: org.apache.commons.dbcp.SQLNestedException: Cannot get a connection, pool error Timeout waiting for idle object
                at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:116)
Caused by: java.util.NoSuchElementException: Timeout waiting for idle object
                at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:1174)
2015-09-08 09:50:54,993 - ERROR [net.shibboleth.idp.consent.flow.ar.AbstractAttributeReleaseAction:150] - Profile Action PopulateAttributeReleaseContext: Unable to locate attribute context

Some ideas ?

Thanks' for help

Jacques Tissot
Université de Fribourg
Switzerland

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://shibboleth.net/pipermail/users/attachments/20150908/122afc11/attachment-0001.html>