NameID insert logic appears wrong for ODBC Session store
Basics
Technical
Logistics
Basics
Technical
Logistics
Description
Occasional INSERT errors occur when attempting to INSERT a NameID context into the 'texts' table. The below log lines show that a search is done using a WHERE clause, to find an existing entry for texts/NameID with an expires > datetime. If that doesn't return an entry, the code attempts to INSERT a new texts/NameID record. But since the key defined for that record is just the combo of context and id (in the below, NameID and Someone@email.com), it's possible for an existing record to exist but not to have been found by the search (because expires time is earlier than specified in search). This can then generate an ODBC error, because of attempting to insert a duplicate key, as below.
There appears to be some built-in retry, and in the logs I looked at, these failed inserts were tried 11 times before code gave up trying that insert.
Log lines:
2015-05-18 09:33:53 DEBUG XMLTooling.StorageService [10186]: search returned no data (t=texts, c=Logout, k=Someone@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:emailAd dress&qu ot;>Someone@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@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@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@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@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@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@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....
Environment
Amazon AMI Linux, with Shib SP 2.5.3, built for Amazon AMI Linux (using SRPM method). Using MySQL 5.1.x.
Occasional INSERT errors occur when attempting to INSERT a NameID context into the 'texts' table. The below log lines show that a search is done using a WHERE clause, to find an existing entry for texts/NameID with an expires > datetime. If that doesn't return an entry, the code attempts to INSERT a new texts/NameID record. But since the key defined for that record is just the combo of context and id (in the below, NameID and Someone@email.com), it's possible for an existing record to exist but not to have been found by the search (because expires time is earlier than specified in search). This can then generate an ODBC error, because of attempting to insert a duplicate key, as below.
There appears to be some built-in retry, and in the logs I looked at, these failed inserts were tried 11 times before code gave up trying that insert.
Log lines:
2015-05-18 09:33:53 DEBUG XMLTooling.StorageService [10186]: search returned no data (t=texts, c=Logout, k=Someone@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:emailAd
dress&qu
ot;>Someone@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@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@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@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@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@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@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....