IdPv3: race condition causes two persistentId to be generated
Dominique Petitpierre
Dominique.Petitpierre at unige.ch
Wed Sep 23 11:28:55 EDT 2015
Hello,
it looks like there is a race condition bug in persistentId generation
when they are stored in a database.
An application (a portal) is displaying the interface of other SPs in
iframes, and in one case there is two iframes for the same SP on one
page. With the new IdpV3 SSO authentication flow this works alright
(one authentication flow by iframe), but sometimes two different
persistentIds are generated and stored, one by each authentication
flow.
You will see in annexe a idp-process.log debug log extract showing
such an occurrence, together with the stored entries in the shibpid
table of the database.
Context:
Shibboleth IdP Version 3.1.2
logback.xml entry:
<logger name="net.shibboleth.idp.saml.nameid" level="DEBUG"/>
From what I understand from the source code it is due to the fact
that, in chronological order:
1) Both threads check in parallel that there is no pre-existent
persistentId in the database.
2) Both threads generate in parallel the same persistentId with the
hash algorithm.
3) One thread checks again if a persistentId already exists in the
database, finds none and stores the persistentId in the database
(base64 format).
4) The second thread checks again if there is already a persistentId
and finds the one stored by the first thread.
5) The second threads generate a new, this time random, persistentId
and stores it in the database (uuid format).
cf. StoredPersistentIdGenerationStrategy.java
http://svn.shibboleth.net/view/java-identity-provider/tags/3.1.2/idp-saml-impl/src/main/java/net/shibboleth/idp/saml/nameid/impl/StoredPersistentIdGenerationStrategy.java?view=markup#l162
We also have observed the case where both threads generate and store
the same persistentId: in that case the race condition timing is such
that in step 4) above the second thread does not find the other
thread's persistentId in the database because it is not there yet. It
is less problematic because it is a duplicate, but still annoying and
not clean.
You probably can reproduce it with a similar setting (two iframes on
the same page pointing to the same SP), and trying enough times as to
trigger the problem, clearing the relevant database entries before
each trial.
One question:
a) Why does StoredPersistentIdGenerationStrategy generate a new
persistentId instead of reporting an error? I.e. IMHO re-assigning
a new persistentId is a delicate matter and should be done only
under the control of a human by a special tool, not the IdP.
Two suggestions:
b) A quick fix would be that at step 4) above, if the persistentId to
be stored is the same as the stored one, then no new persistentId
is generated.
c) To avoid that two identical persistentId be stored (second case
above), may be one could rely on a database (or other storage)
constraint preventing duplicates, and for the second thread to
ignore the duplicate entry error message from the database. (But
this would not work well in a load balanced asynchronously
replicated database cluster unless there is some kind of tolerant
conflict resolution).
Thanks in advance for your answers!
Regards,
Dominique Petitpierre
--
Mr Dominique Petitpierre, user=Dominique.Petitpierre domain=unige.ch
IT Division, University of Geneva, Switzerland
-------------- next part --------------
2015-09-23 13:30:36,734 - INFO [net.shibboleth.idp.log.LogbackLoggingService:240] - jsessionID: - Shibboleth IdP Version 3.1.2
2015-09-23 13:38:05,531 - INFO [net.shibboleth.idp.log.LogbackLoggingService:240] - jsessionID:E0AF179D6E93D33E32585AAF92C47B18 - Shibboleth IdP Version 3.1.2
2015-09-23 13:57:10,127 - INFO [net.shibboleth.idp.authn.impl.ValidateUsernamePasswordAgainstLDAP:179] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Profile Action ValidateUsernamePasswordAgainstLDAP: Login by 'joesmith' succeeded
2015-09-23 13:57:10,260 - DEBUG [net.shibboleth.idp.saml.nameid.impl.StoredPersistentIdGenerationStrategy:106] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Checking for existing, active, stored ID for principal 'joesmith'
2015-09-23 13:57:10,260 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:389] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Selecting active persistent ID entry based on prepared sql statement: SELECT * FROM shibpid WHERE localEntity = ? AND peerEntity = ? AND localId = ? AND deactivationDate IS NULL
2015-09-23 13:57:10,263 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:395] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 1: https://idp-test.unige.ch/idp/shibboleth
2015-09-23 13:57:10,264 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:397] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 2: https://portail-test.unige.ch/shibboleth
2015-09-23 13:57:10,264 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:399] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 3: 1234 at unige.ch
2015-09-23 13:57:10,264 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:402] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Getting active persistent Id entries.
2015-09-23 13:57:10,270 - DEBUG [net.shibboleth.idp.saml.nameid.impl.StoredPersistentIdGenerationStrategy:114] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Located existing stored ID PersistentIdEntry{persistentId:LumlP+f/Q5longsyjSPkonSIxO8=, localEntityId:https://idp-test.unige.ch/idp/shibboleth, recipientEntityId:https://portail-test.unige.ch/shibboleth, sourceId:1234 at unige.ch, principalName:joesmith, peerProvidedId:null, creationTime:2013-03-30 19:08:13.0, deactivationTime:null, }
2015-09-23 13:57:10,344 - INFO [Shibboleth-Audit.SSO:241] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - 20150923T115710Z|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect|_a838bd06d2c1590d6fbecd691e5ec4ef|https://portail-test.unige.ch/shibboleth|http://shibboleth.net/ns/profiles/saml2/sso/browser|https://idp-test.unige.ch/idp/shibboleth|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST|_e5fccc31db79f286bad03a22277d2832|joesmith|urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport|swissEduPersonUniqueID.withoutAttributeEncoder,eduPersonAffiliation,isMemberOf,email,swissEduPersonHomeOrganization,swissEduPersonUniqueID,surname,givenName,swissEduPersonHomeOrganizationType|AAhzZWNyZXQxN1xgAFEaj0PVdfG+p75W1YjQHBBUAlRU4ArGHZtDefpJs1iHlZwOMj+KOFblvDrLAn2OZIo5d63G6U10hWw292f/kvqps8IJYALhiS+otZFtKKz7HTa4cbDbqNRXGE/Cdl0AJnMUqWBAM3hDVpg=|_3d3978195b7c9af113619a33511b6f52
2015-09-23 13:57:11,142 - DEBUG [net.shibboleth.idp.saml.nameid.impl.StoredPersistentIdGenerationStrategy:106] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Checking for existing, active, stored ID for principal 'joesmith'
2015-09-23 13:57:11,143 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:389] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Selecting active persistent ID entry based on prepared sql statement: SELECT * FROM shibpid WHERE localEntity = ? AND peerEntity = ? AND localId = ? AND deactivationDate IS NULL
2015-09-23 13:57:11,146 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:395] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 1: https://idp-test.unige.ch/idp/shibboleth
2015-09-23 13:57:11,147 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:397] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 2: https://swapp-test.unige.ch/general-swapp/shibboleth
2015-09-23 13:57:11,147 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:399] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 3: 1234 at unige.ch
2015-09-23 13:57:11,148 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:402] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Getting active persistent Id entries.
2015-09-23 13:57:11,149 - DEBUG [net.shibboleth.idp.saml.nameid.impl.StoredPersistentIdGenerationStrategy:109] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - No existing, active, stored ID, creating a new one for principal 'joesmith'
2015-09-23 13:57:11,154 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:350] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Selecting number of persistent ID entries based on prepared sql statement: SELECT count(persistentId) FROM shibpid WHERE localEntity = ? AND peerEntity = ? AND localId = ?
2015-09-23 13:57:11,155 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:355] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 1: https://idp-test.unige.ch/idp/shibboleth
2015-09-23 13:57:11,155 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:357] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 2: https://swapp-test.unige.ch/general-swapp/shibboleth
2015-09-23 13:57:11,156 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:359] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 3: 1234 at unige.ch
2015-09-23 13:57:11,170 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:465] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Selecting persistent ID entry based on prepared sql statement: SELECT * FROM shibpid WHERE persistentId = ?
2015-09-23 13:57:11,174 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:471] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 1: kLpfuJY0XtajF/aO8H1Elep27j4=
2015-09-23 13:57:11,177 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:295] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Storing persistent ID entry based on prepared sql statement: INSERT INTO shibpid (localEntity, peerEntity, principalName, localId, persistentId, peerProvidedId, creationDate) VALUES (?, ?, ?, ?, ?, ?, ?)
2015-09-23 13:57:11,179 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:299] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 1: https://idp-test.unige.ch/idp/shibboleth
2015-09-23 13:57:11,179 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:302] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 2: https://swapp-test.unige.ch/general-swapp/shibboleth
2015-09-23 13:57:11,179 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:305] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 3: joesmith
2015-09-23 13:57:11,180 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:307] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 4: 1234 at unige.ch
2015-09-23 13:57:11,180 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:309] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 5: kLpfuJY0XtajF/aO8H1Elep27j4=
2015-09-23 13:57:11,181 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:313] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 6: 12
2015-09-23 13:57:11,190 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:321] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 7: 2015-09-23 13:57:11.181
2015-09-23 13:57:11,191 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:324] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - com.mysql.jdbc.JDBC4PreparedStatement at 2e51769f: INSERT INTO shibpid (localEntity, peerEntity, principalName, localId, persistentId, peerProvidedId, creationDate) VALUES ('https://idp-test.unige.ch/idp/shibboleth', 'https://swapp-test.unige.ch/general-swapp/shibboleth', 'joesmith', '1234 at unige.ch', 'kLpfuJY0XtajF/aO8H1Elep27j4=', null, '2015-09-23 13:57:11')
2015-09-23 13:57:11,193 - DEBUG [net.shibboleth.idp.saml.nameid.impl.StoredPersistentIdGenerationStrategy:106] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Checking for existing, active, stored ID for principal 'joesmith'
2015-09-23 13:57:11,194 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:389] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Selecting active persistent ID entry based on prepared sql statement: SELECT * FROM shibpid WHERE localEntity = ? AND peerEntity = ? AND localId = ? AND deactivationDate IS NULL
2015-09-23 13:57:11,195 - DEBUG [net.shibboleth.idp.saml.nameid.impl.StoredPersistentIdGenerationStrategy:106] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Checking for existing, active, stored ID for principal 'joesmith'
2015-09-23 13:57:11,195 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:389] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Selecting active persistent ID entry based on prepared sql statement: SELECT * FROM shibpid WHERE localEntity = ? AND peerEntity = ? AND localId = ? AND deactivationDate IS NULL
2015-09-23 13:57:11,197 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:395] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 1: https://idp-test.unige.ch/idp/shibboleth
2015-09-23 13:57:11,197 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:397] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 2: https://swapp-test.unige.ch/general-swapp/shibboleth
2015-09-23 13:57:11,198 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:399] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 3: 1234 at unige.ch
2015-09-23 13:57:11,198 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:402] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Getting active persistent Id entries.
2015-09-23 13:57:11,200 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:395] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 1: https://idp-test.unige.ch/idp/shibboleth
2015-09-23 13:57:11,200 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:397] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 2: https://swapp-test.unige.ch/news-swapp/shibboleth
2015-09-23 13:57:11,201 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:399] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 3: 1234 at unige.ch
2015-09-23 13:57:11,201 - DEBUG [net.shibboleth.idp.saml.nameid.impl.StoredPersistentIdGenerationStrategy:112] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Created stored ID 'PersistentIdEntry{persistentId:kLpfuJY0XtajF/aO8H1Elep27j4=, localEntityId:https://idp-test.unige.ch/idp/shibboleth, recipientEntityId:https://swapp-test.unige.ch/general-swapp/shibboleth, sourceId:1234 at unige.ch, principalName:joesmith, peerProvidedId:null, creationTime:2015-09-23 13:57:11.176, deactivationTime:null, }'
2015-09-23 13:57:11,206 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:402] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Getting active persistent Id entries.
2015-09-23 13:57:11,207 - DEBUG [net.shibboleth.idp.saml.nameid.impl.StoredPersistentIdGenerationStrategy:109] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - No existing, active, stored ID, creating a new one for principal 'joesmith'
2015-09-23 13:57:11,211 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:350] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Selecting number of persistent ID entries based on prepared sql statement: SELECT count(persistentId) FROM shibpid WHERE localEntity = ? AND peerEntity = ? AND localId = ?
2015-09-23 13:57:11,211 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:355] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 1: https://idp-test.unige.ch/idp/shibboleth
2015-09-23 13:57:11,212 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:357] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 2: https://swapp-test.unige.ch/news-swapp/shibboleth
2015-09-23 13:57:11,212 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:359] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 3: 1234 at unige.ch
2015-09-23 13:57:11,213 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:465] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Selecting persistent ID entry based on prepared sql statement: SELECT * FROM shibpid WHERE persistentId = ?
2015-09-23 13:57:11,218 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:471] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 1: PabHneRd9qHdRtAXpETQhqS7cBU=
2015-09-23 13:57:11,220 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:295] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Storing persistent ID entry based on prepared sql statement: INSERT INTO shibpid (localEntity, peerEntity, principalName, localId, persistentId, peerProvidedId, creationDate) VALUES (?, ?, ?, ?, ?, ?, ?)
2015-09-23 13:57:11,222 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:299] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 1: https://idp-test.unige.ch/idp/shibboleth
2015-09-23 13:57:11,222 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:302] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 2: https://swapp-test.unige.ch/news-swapp/shibboleth
2015-09-23 13:57:11,223 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:305] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 3: joesmith
2015-09-23 13:57:11,223 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:307] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 4: 1234 at unige.ch
2015-09-23 13:57:11,224 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:309] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 5: PabHneRd9qHdRtAXpETQhqS7cBU=
2015-09-23 13:57:11,224 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:313] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 6: 12
2015-09-23 13:57:11,225 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:321] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 7: 2015-09-23 13:57:11.225
2015-09-23 13:57:11,230 - DEBUG [net.shibboleth.idp.saml.nameid.impl.StoredPersistentIdGenerationStrategy:109] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - No existing, active, stored ID, creating a new one for principal 'joesmith'
2015-09-23 13:57:11,232 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:350] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Selecting number of persistent ID entries based on prepared sql statement: SELECT count(persistentId) FROM shibpid WHERE localEntity = ? AND peerEntity = ? AND localId = ?
2015-09-23 13:57:11,232 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:355] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 1: https://idp-test.unige.ch/idp/shibboleth
2015-09-23 13:57:11,233 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:357] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 2: https://swapp-test.unige.ch/general-swapp/shibboleth
2015-09-23 13:57:11,233 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:324] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - com.mysql.jdbc.JDBC4PreparedStatement at 7fa4765f: INSERT INTO shibpid (localEntity, peerEntity, principalName, localId, persistentId, peerProvidedId, creationDate) VALUES ('https://idp-test.unige.ch/idp/shibboleth', 'https://swapp-test.unige.ch/news-swapp/shibboleth', 'joesmith', '1234 at unige.ch', 'PabHneRd9qHdRtAXpETQhqS7cBU=', null, '2015-09-23 13:57:11')
2015-09-23 13:57:11,233 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:359] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 3: 1234 at unige.ch
2015-09-23 13:57:11,259 - INFO [Shibboleth-Audit.SSO:241] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - 20150923T115711Z|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect|_dfe5e69be55ec097e8371b833f3a146d|https://swapp-test.unige.ch/general-swapp/shibboleth|http://shibboleth.net/ns/profiles/saml2/sso/browser|https://idp-test.unige.ch/idp/shibboleth|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST|_533089cbd777ed968c117f0205fdc77a|joesmith|urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport|employeeType,swissEduPersonUniqueID.withoutAttributeEncoder,eduPersonAffiliation,isMemberOf,email,swissEduPersonHomeOrganization,unigeChEmployeeOUCode,swissEduPersonUniqueID,surname,givenName,swissEduPersonHomeOrganizationType,eduPersonTargetedID|AAhzZWNyZXQxN6l9Oo0aCTBbFbgaa/H0pGw/7zJ8j8IMMuv9Gd/vzli/n+RerQgpo6mkvwEAlziZz2RXo5YOC5/GD15/vG6DtEEEQezW7k6opYnM78odUrSA903D2y/dS/uPi2vIEr1gp9RR9heee+JEF/07Vw2KLuzcXITAI+Q=|_533a5a6476b7b7e5533a077455c5f1fc
2015-09-23 13:57:11,265 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:465] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Selecting persistent ID entry based on prepared sql statement: SELECT * FROM shibpid WHERE persistentId = ?
2015-09-23 13:57:11,266 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:471] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 1: b1926281-8b0f-4ff5-bfde-d0a3dec2fde8
2015-09-23 13:57:11,268 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:295] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Storing persistent ID entry based on prepared sql statement: INSERT INTO shibpid (localEntity, peerEntity, principalName, localId, persistentId, peerProvidedId, creationDate) VALUES (?, ?, ?, ?, ?, ?, ?)
2015-09-23 13:57:11,269 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:299] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 1: https://idp-test.unige.ch/idp/shibboleth
2015-09-23 13:57:11,269 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:302] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 2: https://swapp-test.unige.ch/general-swapp/shibboleth
2015-09-23 13:57:11,270 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:305] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 3: joesmith
2015-09-23 13:57:11,270 - DEBUG [net.shibboleth.idp.saml.nameid.impl.StoredPersistentIdGenerationStrategy:112] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Created stored ID 'PersistentIdEntry{persistentId:PabHneRd9qHdRtAXpETQhqS7cBU=, localEntityId:https://idp-test.unige.ch/idp/shibboleth, recipientEntityId:https://swapp-test.unige.ch/news-swapp/shibboleth, sourceId:1234 at unige.ch, principalName:joesmith, peerProvidedId:null, creationTime:2015-09-23 13:57:11.219, deactivationTime:null, }'
2015-09-23 13:57:11,278 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:307] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 4: 1234 at unige.ch
2015-09-23 13:57:11,278 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:309] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 5: b1926281-8b0f-4ff5-bfde-d0a3dec2fde8
2015-09-23 13:57:11,279 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:313] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 6: 12
2015-09-23 13:57:11,279 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:321] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Stored Id Store: Setting prepared statement parameter 7: 2015-09-23 13:57:11.279
2015-09-23 13:57:11,284 - DEBUG [net.shibboleth.idp.saml.nameid.impl.JDBCPersistentIdStore:324] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - com.mysql.jdbc.JDBC4PreparedStatement at 28d7c524: INSERT INTO shibpid (localEntity, peerEntity, principalName, localId, persistentId, peerProvidedId, creationDate) VALUES ('https://idp-test.unige.ch/idp/shibboleth', 'https://swapp-test.unige.ch/general-swapp/shibboleth', 'joesmith', '1234 at unige.ch', 'b1926281-8b0f-4ff5-bfde-d0a3dec2fde8', null, '2015-09-23 13:57:11')
2015-09-23 13:57:11,298 - DEBUG [net.shibboleth.idp.saml.nameid.impl.StoredPersistentIdGenerationStrategy:112] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - Created stored ID 'PersistentIdEntry{persistentId:b1926281-8b0f-4ff5-bfde-d0a3dec2fde8, localEntityId:https://idp-test.unige.ch/idp/shibboleth, recipientEntityId:https://swapp-test.unige.ch/general-swapp/shibboleth, sourceId:1234 at unige.ch, principalName:joesmith, peerProvidedId:null, creationTime:2015-09-23 13:57:11.267, deactivationTime:null, }'
2015-09-23 13:57:11,359 - INFO [Shibboleth-Audit.SSO:241] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - 20150923T115711Z|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect|_a386f672c7e140e945c5050af053ccd4|https://swapp-test.unige.ch/news-swapp/shibboleth|http://shibboleth.net/ns/profiles/saml2/sso/browser|https://idp-test.unige.ch/idp/shibboleth|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST|_6456187a1d5918e6a0ef4ea2f15bf554|joesmith|urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport|swissEduPersonUniqueID.withoutAttributeEncoder,eduPersonAffiliation,email,swissEduPersonHomeOrganization,swissEduPersonUniqueID,surname,givenName,swissEduPersonHomeOrganizationType,eduPersonTargetedID|AAhzZWNyZXQxN51xW6H2NOGTYIqmzjmb6WmRa4tuU+yz0bNZAD97m4yBfAK00Oi7LsqmVn/S3Mu/zyIxOwDdX45lXu5QubEjy3rr73XzU682ymWPnzSkI6BQmDevvLzhYir275Xs8983GmIdfGDfHzzgwLoQC37JSAtktls=|_5a8f137ea2804a616ea9dda3630ba2c0
2015-09-23 13:57:11,372 - INFO [Shibboleth-Audit.SSO:241] - jsessionID:61C79ED74F06F13CA1A557DE8E3BDDF3 - 20150923T115711Z|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect|_d775165f8ae2b5758903c9e7a65d4d2d|https://swapp-test.unige.ch/general-swapp/shibboleth|http://shibboleth.net/ns/profiles/saml2/sso/browser|https://idp-test.unige.ch/idp/shibboleth|urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST|_c59b2414ec40008bda3c00ecd71f4ba2|joesmith|urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport|employeeType,swissEduPersonUniqueID.withoutAttributeEncoder,eduPersonAffiliation,isMemberOf,email,swissEduPersonHomeOrganization,unigeChEmployeeOUCode,swissEduPersonUniqueID,surname,givenName,swissEduPersonHomeOrganizationType,eduPersonTargetedID|AAhzZWNyZXQxNzL3qt9VTcGh2u726sYPbqSx5wudwHD0sS+jj0bT/RNZEvsXy68KOAg9uYT2sOsrxd0DdG64/RyAwVVt+CeoaeOYdZ/jDbc+Vo/jsSZd956lUO0AjdaUIUUNj2TZlpyUySSC4HMErwKuDY/5/pKczVwHA8UL/9c=|_bb3fa2035ccc42dd979efb90a309a00c
-------------- next part --------------
localEntity peerEntity principalName localId persistentId peerProvidedId creationDate deactivationDate
https://idp-test.unige.ch/idp/shibboleth https://swapp-test.unige.ch/general-swapp/shibboleth joesmith 1234 at unige.ch kLpfuJY0XtajF/aO8H1Elep27j4= NULL 2015-09-23 13:57:11 NULL
https://idp-test.unige.ch/idp/shibboleth https://swapp-test.unige.ch/general-swapp/shibboleth joesmith 1234 at unige.ch b1926281-8b0f-4ff5-bfde-d0a3dec2fde8 NULL 2015-09-23 13:57:11 NULL
More information about the users
mailing list