Too long conversations between IDP and SP

[TISSOT Jacques]

Dear Community, especially those who answered to my problem,

The problem solved from itself when I cut off the remote PSQL database (with replication on the two IDP servers) by simply link it locally. Something had to be wrong with the replication. Nothing to do with the DNS RoundRobin. It could cause problems somehow, but not in that case.

I have to tune better the replication of my postgres database.

Thanks to all

J. Tissot

From: users [mailto:users-bounces at shibboleth.net] On Behalf Of TISSOT Jacques
Sent: mardi 8 septembre 2015 16:52
To: users at shibboleth.net
Subject: Too long conversations between IDP and SP

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/20150914/9ecde000/attachment-0001.html>