IDP V3: LockTimeoutException with remote PG DB

Wed Sep 30 05:47:49 EDT 2015

Dear Community,

The following observation appears only when IDP is asking PG DB server remotely. I tried different (in global.xml) maxActive and maxIdle jdbc connectors (up to 32) without solving the problem. The problem does not appear when IDP is asking PG DB locally.

I thought first it will be caused by the replication. But, it happens the same way if DB is not replicated.

Behaviour:

By peaks of login, suddenly the IDP authenticate a series of users, the PG server stucks on some transaction (see below), and more or less than 40s all the authenticated users get their audit release at the same time, eg:

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

In worse case, the use can lose its connection !

See below the different extracts of logs.

Idp-process.log - Error:

2015-09-30 10:29:33,686 - 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)

Postgresql-9.4.log:

2015-09-30 10:00:18 CEST [22593-85] shibboleth at shibboleth LOG:  process 22593 still waiting for ShareLock on transaction 648832 after 1000.109 ms
2015-09-30 10:00:18 CEST [22593-86] shibboleth at shibboleth DETAIL:  Process holding the lock: 22582. Wait queue: 22571, 22594, 22585, 22327, 22595, 22588, 22581, 22586, 22326, 22328, 22593.
2015-09-30 10:00:18 CEST [22593-87] shibboleth at shibboleth CONTEXT:  while locking tuple (387,42) in relation "storagerecords"
2015-09-30 10:00:18 CEST [22593-88] shibboleth at shibboleth STATEMENT:  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=$1 and jpastorage0_.id=$2 for share
..
2015-09-30 10:00:25 CEST [22327-89] shibboleth at shibboleth LOG:  process 22327 acquired ShareLock on transaction 648832 after 36103.378 ms
2015-09-30 10:00:25 CEST [22327-90] shibboleth at shibboleth CONTEXT:  while locking tuple (364,21) in relation "storagerecords"
2015-09-30 10:00:25 CEST [22327-91] shibboleth at shibboleth STATEMENT:  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=$1 and jpastorage0_.id=$2 for share

Config: 

IDP server: 

### Operating Environment Information
operating_system: Linux (RAM: 2GB, 1 CPU)
operating_system_version: 3.16.0-4-amd64
operating_system_architecture: amd64
jdk_version: 1.7.0_79
available_cores: 1
used_memory: 643 MB
maximum_memory: 643 MB

### Identity Provider Information
idp_version: 3.1.1

PG-server: 

Postgresql 9.4 on Debian 8.1, 1 CPU, 1 GB RAM

Java connectors:

<bean id="shibboleth.PostgreSQLDataSource"
          class="org.apache.commons.dbcp.BasicDataSource"
          p:driverClassName="org.postgresql.Driver"
          p:url="jdbc:postgresql://remote-db-ip/shibboleth"
          p:username="shibboleth"
          p:password="%{psql.password}"
          p:initialSize="4"
          p:maxActive="16"
          p:maxIdle="16"
          p:maxWait="40000"
          p:testOnBorrow="true"
          p:validationQuery="select 1"
          p:validationQueryTimeout="40" />

Thank You for taking time to help me to understand the phenomenon.

Best regards,
Jacques

Jacques Tissot
Université de Fribourg
Switzerland