ODBC Session store for Shibboleth SP, error with NameID insert

Michael A Grady mgrady at unicon.net
Thu May 21 15:01:56 EDT 2015


This is Shib SP 2.5.3, built for Amazon AMI Linux (using SRPM method). Multiple instances which have been setup to use the NativeSPODBCStorageService ( https://wiki.shibboleth.net/confluence/display/SHIB2/NativeSPODBCStorageService ). With MySQL 5.1.x. In general, it seems to be working fine, but I'm wondering about an occasional INSERT error for the 'texts' table, with context NameID. The following log snippet, with some obfuscation, shows the error.

The SP determines it needs to insert a new session, and it succeeds in starting to store a new session. But when it tires to find an existing entry for texts/NameID with an expires > datetime, ti doesn't find any, so goes to INSERT a new one. That generates the error, because the key for such an entry already exists (key is combo of context and id, in this case NameID and Someone at email.com.) It appears to generally repeat the attempt to insert for 11 times, before it gives up, and considers the session created without that.

I've never looked carefully at the SP's session storage. Just wondering if an error like this would be indicative of any kind of config error for the ODBC setup or not. However, most of the time, that INSERT is working just fine.

2015-05-18 09:33:53 DEBUG XMLTooling.StorageService [10186]: search returned no data (t=texts, c=Logout, k=Someone at email.com)
2015-05-18 09:33:53 DEBUG Shibboleth.SessionCache [10186]: storing new session...
2015-05-18 09:33:53 DEBUG XMLTooling.StorageService [10186]: SQLPrepare succeeded. SQL: INSERT INTO texts VALUES (?,?,{ts '2015-05-18 10:33:53'},1,?)
2015-05-18 09:33:53 DEBUG XMLTooling.StorageService [10186]: SQLBindParam succeeded (context = _c9aad74xxxxxxxx...)
2015-05-18 09:33:53 DEBUG XMLTooling.StorageService [10186]: SQLBindParam succeeded (key = session)
2015-05-18 09:33:53 DEBUG XMLTooling.StorageService [10186]: SQLBindParam succeeded (value = <wddxPacket version="1.0" lowercase="no"><header/><data><struct name="_c9aad74xxxxxxxx..."><var name="version"><number>1</number></var><var name="application_id"><string>default</string></var><var name="expires"><string>2015-05-18T10:36:53Z</string></var><var name="client_addr"><struct><var name="4"><string>10.0.104.121</string></var></struct></var><var name="entity_id"><string>https://idp.org.com/idp</string></var><var name="protocol"><string>urn:oasis:names:tc:SAML:2.0:protocol</string></var><var name="authn_instant"><string>2015-05-18T09:33:53Z</string></var><var name="session_index"><string>uuid665f.....</string></var><var name="authncontext_class"><string>urn:oasis:names:tc:SAML:2.0:ac:classes:Password</string></var><var name="nameid"><string><saml:NameID xmlns:saml="urn:oasis:names:tc:SAML:2.0:assertion" Format="urn:oasis:names:tc:SAML:1.1:nameid-format:emailAddress">Someone at email.com</saml:NameID></string></var><var name="attributes"><array length="2"><struct><var name="distinguishedName"><array length="1"><string>CN=LASTNAME\, FIRSTNAME,OU=USERS,DC=ORG,DC=COM</string></array></var></struct><struct><var name="userId"><array length="1"><string>someone</string></array></var></struct></array></var></struct></data></wddxPacket>)
2015-05-18 09:33:53 DEBUG XMLTooling.StorageService [10186]: SQLExecute of insert succeeded
2015-05-18 09:33:53 DEBUG XMLTooling.StorageService [10186]: SQL: SELECT version,expires,CASE version WHEN 0 THEN null ELSE value END FROM texts WHERE context='NameID' AND id='Someone at email.com' AND expires > {ts '2015-05-18 09:33:53'}
2015-05-18 09:33:53 DEBUG XMLTooling.StorageService [10186]: search returned no data (t=texts, c=NameID, k=Someone at email.com)
2015-05-18 09:33:54 DEBUG XMLTooling.StorageService [10186]: SQLPrepare succeeded. SQL: INSERT INTO texts VALUES (?,?,{ts '2015-05-18 10:36:53'},1,?)
2015-05-18 09:33:54 DEBUG XMLTooling.StorageService [10186]: SQLBindParam succeeded (context = NameID)
2015-05-18 09:33:54 DEBUG XMLTooling.StorageService [10186]: SQLBindParam succeeded (key = Someone at email.com)
2015-05-18 09:33:54 DEBUG XMLTooling.StorageService [10186]: SQLBindParam succeeded (value = <wddxPacket version="1.0" lowercase="no"><header/><data><struct><var name="uuid665f....."><array length="1"><string>_c9aad74xxxxxxxx...</string></array></var></struct></data></wddxPacket>)
2015-05-18 09:33:54 ERROR XMLTooling.StorageService [10186]: insert record failed (t=texts, c=NameID, k=Someone at email.com)
2015-05-18 09:33:54 ERROR XMLTooling.StorageService [10186]: ODBC Error: 23000:1:1062:[MySQL][ODBC 5.1 Driver][mysqld-5.1.73-log]Duplicate entry 'NameID-Someone at email.com' for key 'PRIMARY'
2015-05-18 09:33:54 DEBUG XMLTooling.StorageService [10186]: SQL: SELECT version,expires,CASE version WHEN 0 THEN null ELSE value END FROM texts WHERE context='NameID' AND id='Someone at email.com' AND expires > {ts '2015-05-18 09:33:54'}

.... tries 11 times

2015-05-18 09:33:54 ERROR Shibboleth.SessionCache [10186]: error storing back mapping of NameID for logout: Exceeded retry limit.
2015-05-18 09:33:54 INFO Shibboleth.SessionCache [10186]: new session created: ID (_c9aad74....

--
Michael A. Grady
IAM Architect, Unicon, Inc.



More information about the users mailing list