storedId connector not generating old style persistent id correctly?
Key details
Basics
Technical
Logistics
Basics
Technical
Logistics
Description
I've just set up the storedId connector on my clustered (terracotta) 2.1.2 installation, and I'm seeing unexpected behaviour when it comes to the process that I believe I should see - i.e. the storedId connector checks the database for an existing generated persistent id for that user/sp/idp combination. If it doesn't exist, it creates one in the same style as shib 1 did / the computedId connector does, and stores it in the database. Only when that is subsequently revoked does it create a new type 4 UUID format persistent id.
What i'm actually seeing is this - the storedId connector is configured against a completely empty mysql database with table configured as per the instructions on the wiki (Snippet below to prove that it's genuinely empty). The stored Id connector checks the database, and says "Generated persistent ID was already assigned to another user, regenerating". It then creates a type 4 uuid format persistent id and stores it in the database. (The next time that user authenticates, the logs show this value being picked up straight from the database). So it's not creating the old style id initially as I'd expect...
Relevant logs below (much irrelevant stuff snipped for brevity). Note that I've redacted principalName/localId (which are different as on my IdP users log in with username but principalName (and things like targetedId) use that person's internal unique identity number as a sourceAttribute).
==== stored Id database ==== mysql> select * from shibpid; Empty set (0.00 sec) =====
==== Logs from initial loading of the IdP relating to storedId ====
14:43:37.498 - INFO [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.AbstractResolutionPlugInBeanDefinitionParser:54] - Parsing configuration for DataConnector plugin with ID: storedId 14:43:37.499 - DEBUG [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.AbstractResolutionPlugInBeanDefinitionParser:60] - Setting the following attribute definition dependencies for plugin storedId: [myLDAP] 14:43:37.882 - DEBUG [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.dataConnector.StoredIDDataConnectorBeanDefinitionParser:212] - Created application managed data source for data connector storedId
14:43:38.422 - INFO [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.AbstractResolutionPlugInBeanDefinitionParser:54] - Parsing configuration for AttributeDefinition plugin with ID: eduPersonTargetedID.old 14:43:38.423 - DEBUG [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.AbstractResolutionPlugInBeanDefinitionParser:60] - Setting the following attribute definition dependencies for plugin eduPersonTargetedID.old: [storedId] 14:43:38.424 - DEBUG [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.attributeDefinition.BaseAttributeDefinitionBeanDefinitionParser:57] - Setting source attribute ID for attribute definition eduPersonTargetedID.old to: storedId 14:43:38.424 - DEBUG [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.attributeDefinition.BaseAttributeDefinitionBeanDefinitionParser:81] - Attribute definition eduPersonTargetedID.old produces attributes that are only dependencies: false 14:43:38.425 - DEBUG [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.attributeDefinition.ScopedAttributeDefinitionBeanDefinitionParser:52] - Setting scope of attribute definition eduPersonTargetedID.old to: cardiff.ac.uk
14:43:38.427 - INFO [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.AbstractResolutionPlugInBeanDefinitionParser:54] - Parsing configuration for AttributeDefinition plugin with ID: eduPersonTargetedID 14:43:38.428 - DEBUG [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.AbstractResolutionPlugInBeanDefinitionParser:60] - Setting the following attribute definition dependencies for plugin eduPersonTargetedID: [storedId] 14:43:38.429 - DEBUG [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.attributeDefinition.BaseAttributeDefinitionBeanDefinitionParser:57] - Setting source attribute ID for attribute definition eduPersonTargetedID to: storedId 14:43:38.429 - DEBUG [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.attributeDefinition.BaseAttributeDefinitionBeanDefinitionParser:81] - Attribute definition eduPersonTargetedID produces attributes that are only dependencies: false
14:43:39.621 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:479] - Loading 3 data connectors 14:43:39.623 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:489] - Loading 32 attribute definitions 14:43:39.626 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:499] - Loading 3 principal connectors 14:43:39.715 - INFO [edu.internet2.middleware.shibboleth.common.config.BaseService:179] - shibboleth.AttributeResolver service configuration loaded
==== Logs from resolving the attributes for the successfully authenticated user relating to storedId =====
14:44:59.873 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294] - Resolving attribute eduPersonTargetedID.old for principal [redacted] 14:44:59.873 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:334] - Resolving data connector storedId for principal [redacted] 14:44:59.874 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:267] - Selecting active persistent ID entry based on prepared sql statement: SELECT * FROM shibpid WHERE localEntity = ? AND peerEntity = ? AND localId = ? AND deactivationDate IS NULL 14:45:00.754 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:272] - Setting prepared statement parameter 1: https://idp-dev.cardiff.ac.uk/idp/shibboleth 14:45:00.755 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:274] - Setting prepared statement parameter 2: https://shib-sp-dev.cf.ac.uk/shibboleth 14:45:00.756 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:276] - Setting prepared statement parameter 3: [redacted] 14:45:00.756 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:279] - Getting active persistent Id entries. 14:45:00.795 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:461] - 0 persistent ID entries retrieved 14:45:00.800 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:117] - Selecting number of persistent ID entries based on prepared sql statement: SELECT count(persistentId) FROM shibpid WHERE localEntity = ? AND peerEntity = ? AND localId = ? 14:45:00.801 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:120] - Setting prepared statement parameter 1: https://idp-dev.cardiff.ac.uk/idp/shibboleth 14:45:00.802 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:122] - Setting prepared statement parameter 2: https://shib-sp-dev.cf.ac.uk/shibboleth 14:45:00.802 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:124] - Setting prepared statement parameter 3: [redacted] 14:45:00.804 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDDataConnector:258] - Generated persistent ID was already assigned to another user, regenerating 14:45:00.805 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:216] - Selecting persistent ID entry based on prepared sql statement: SELECT * FROM shibpid WHERE persistentId = ? 14:45:00.805 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:222] - Setting prepared statement parameter 1: a6a69b22-41f4-42d8-ab3f-0c2424879f52 14:45:00.806 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:461] - 0 persistent ID entries retrieved 14:45:00.808 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:377] - Storing persistent ID entry based on prepared sql statement: INSERT INTO shibpid (localEntity, peerEntity, principalName, localId, persistentId, peerProvidedId, creationDate) VALUES (?, ?, ?, ?, ?, ?, ?) 14:45:00.808 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:380] - Setting prepared statement parameter 1: https://idp-dev.cardiff.ac.uk/idp/shibboleth 14:45:00.809 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:382] - Setting prepared statement parameter 2: https://shib-sp-dev.cf.ac.uk/shibboleth 14:45:00.810 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:384] - Setting prepared statement parameter 3: [redacted] 14:45:00.810 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:386] - Setting prepared statement parameter 4: [redacted] 14:45:00.811 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:388] - Setting prepared statement parameter 5: a6a69b22-41f4-42d8-ab3f-0c2424879f52 14:45:00.811 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:392] - Setting prepared statement parameter 6: 0 14:45:00.812 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:399] - Setting prepared statement parameter 7: 2009-06-25 14:45:00.812 14:45:00.823 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDDataConnector:176] - Created stored ID PersistentIdEntry{persistentId:a6a69b22-41f4-42d8-ab3f-0c2424879f52, localEntityId:https://idp-dev.cardiff.ac.uk/idp/shibboleth, peerEntityId:https://shib-sp-dev.cf.ac.uk/shibboleth, localId:[redacted], principalName:[redacted], peerProvidedId:null, creationTime:2009-06-25 14:45:00.807, deactivationTime:null, } 14:45:00.823 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316] - Resolved attribute eduPersonTargetedID.old containing 1 values
I've just set up the storedId connector on my clustered (terracotta) 2.1.2 installation, and I'm seeing unexpected behaviour when it comes to the process that I believe I should see - i.e. the storedId connector checks the database for an existing generated persistent id for that user/sp/idp combination. If it doesn't exist, it creates one in the same style as shib 1 did / the computedId connector does, and stores it in the database. Only when that is subsequently revoked does it create a new type 4 UUID format persistent id.
What i'm actually seeing is this - the storedId connector is configured against a completely empty mysql database with table configured as per the instructions on the wiki (Snippet below to prove that it's genuinely empty). The stored Id connector checks the database, and says "Generated persistent ID was already assigned to another user, regenerating". It then creates a type 4 uuid format persistent id and stores it in the database. (The next time that user authenticates, the logs show this value being picked up straight from the database). So it's not creating the old style id initially as I'd expect...
Relevant logs below (much irrelevant stuff snipped for brevity). Note that I've redacted principalName/localId (which are different as on my IdP users log in with username but principalName (and things like targetedId) use that person's internal unique identity number as a sourceAttribute).
==== stored Id database ====
mysql> select * from shibpid;
Empty set (0.00 sec)
=====
==== Logs from initial loading of the IdP relating to storedId ====
14:43:36.467 - DEBUG [edu.internet2.middleware.shibboleth.common.config.OpensamlConfigBean:56] - Loading OpenSAML configuration file: jar:file:/usr/local/apache-tomcat-5.5.17/work/Catalina/localhost/idp/WEB-INF/lib/shibboleth-common-1.1.2.jar!/shibboleth-saml-ext-config.xml
14:43:37.498 - INFO [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.AbstractResolutionPlugInBeanDefinitionParser:54] - Parsing configuration for DataConnector plugin with ID: storedId
14:43:37.499 - DEBUG [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.AbstractResolutionPlugInBeanDefinitionParser:60] - Setting the following attribute definition dependencies for plugin storedId: [myLDAP]
14:43:37.882 - DEBUG [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.dataConnector.StoredIDDataConnectorBeanDefinitionParser:212] - Created application managed data source for data connector storedId
14:43:38.422 - INFO [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.AbstractResolutionPlugInBeanDefinitionParser:54] - Parsing configuration for AttributeDefinition plugin with ID: eduPersonTargetedID.old
14:43:38.423 - DEBUG [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.AbstractResolutionPlugInBeanDefinitionParser:60] - Setting the following attribute definition dependencies for plugin eduPersonTargetedID.old: [storedId]
14:43:38.424 - DEBUG [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.attributeDefinition.BaseAttributeDefinitionBeanDefinitionParser:57] - Setting source attribute ID for attribute definition eduPersonTargetedID.old to: storedId
14:43:38.424 - DEBUG [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.attributeDefinition.BaseAttributeDefinitionBeanDefinitionParser:81] - Attribute definition eduPersonTargetedID.old produces attributes that are only dependencies: false
14:43:38.425 - DEBUG [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.attributeDefinition.ScopedAttributeDefinitionBeanDefinitionParser:52] - Setting scope of attribute definition eduPersonTargetedID.old to: cardiff.ac.uk
14:43:38.427 - INFO [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.AbstractResolutionPlugInBeanDefinitionParser:54] - Parsing configuration for AttributeDefinition plugin with ID: eduPersonTargetedID
14:43:38.428 - DEBUG [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.AbstractResolutionPlugInBeanDefinitionParser:60] - Setting the following attribute definition dependencies for plugin eduPersonTargetedID: [storedId]
14:43:38.429 - DEBUG [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.attributeDefinition.BaseAttributeDefinitionBeanDefinitionParser:57] - Setting source attribute ID for attribute definition eduPersonTargetedID to: storedId
14:43:38.429 - DEBUG [edu.internet2.middleware.shibboleth.common.config.attribute.resolver.attributeDefinition.BaseAttributeDefinitionBeanDefinitionParser:81] - Attribute definition eduPersonTargetedID produces attributes that are only dependencies: false
14:43:39.621 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:479] - Loading 3 data connectors
14:43:39.623 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:489] - Loading 32 attribute definitions
14:43:39.626 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:499] - Loading 3 principal connectors
14:43:39.715 - INFO [edu.internet2.middleware.shibboleth.common.config.BaseService:179] - shibboleth.AttributeResolver service configuration loaded
==== Logs from resolving the attributes for the successfully authenticated user relating to storedId =====
14:44:59.873 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294] - Resolving attribute eduPersonTargetedID.old for principal [redacted]
14:44:59.873 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:334] - Resolving data connector storedId for principal [redacted]
14:44:59.874 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:267] - Selecting active persistent ID entry based on prepared sql statement: SELECT * FROM shibpid WHERE localEntity = ? AND peerEntity = ? AND localId = ? AND deactivationDate IS NULL
14:45:00.754 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:272] - Setting prepared statement parameter 1: https://idp-dev.cardiff.ac.uk/idp/shibboleth
14:45:00.755 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:274] - Setting prepared statement parameter 2: https://shib-sp-dev.cf.ac.uk/shibboleth
14:45:00.756 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:276] - Setting prepared statement parameter 3: [redacted]
14:45:00.756 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:279] - Getting active persistent Id entries.
14:45:00.795 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:461] - 0 persistent ID entries retrieved
14:45:00.800 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:117] - Selecting number of persistent ID entries based on prepared sql statement: SELECT count(persistentId) FROM shibpid WHERE localEntity = ? AND peerEntity = ? AND localId = ?
14:45:00.801 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:120] - Setting prepared statement parameter 1: https://idp-dev.cardiff.ac.uk/idp/shibboleth
14:45:00.802 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:122] - Setting prepared statement parameter 2: https://shib-sp-dev.cf.ac.uk/shibboleth
14:45:00.802 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:124] - Setting prepared statement parameter 3: [redacted]
14:45:00.804 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDDataConnector:258] - Generated persistent ID was already assigned to another user, regenerating
14:45:00.805 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:216] - Selecting persistent ID entry based on prepared sql statement: SELECT * FROM shibpid WHERE persistentId = ?
14:45:00.805 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:222] - Setting prepared statement parameter 1: a6a69b22-41f4-42d8-ab3f-0c2424879f52
14:45:00.806 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:461] - 0 persistent ID entries retrieved
14:45:00.808 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:377] - Storing persistent ID entry based on prepared sql statement: INSERT INTO shibpid (localEntity, peerEntity, principalName, localId, persistentId, peerProvidedId, creationDate) VALUES (?, ?, ?, ?, ?, ?, ?)
14:45:00.808 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:380] - Setting prepared statement parameter 1: https://idp-dev.cardiff.ac.uk/idp/shibboleth
14:45:00.809 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:382] - Setting prepared statement parameter 2: https://shib-sp-dev.cf.ac.uk/shibboleth
14:45:00.810 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:384] - Setting prepared statement parameter 3: [redacted]
14:45:00.810 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:386] - Setting prepared statement parameter 4: [redacted]
14:45:00.811 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:388] - Setting prepared statement parameter 5: a6a69b22-41f4-42d8-ab3f-0c2424879f52
14:45:00.811 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:392] - Setting prepared statement parameter 6: 0
14:45:00.812 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDStore:399] - Setting prepared statement parameter 7: 2009-06-25 14:45:00.812
14:45:00.823 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.dataConnector.StoredIDDataConnector:176] - Created stored ID PersistentIdEntry{persistentId:a6a69b22-41f4-42d8-ab3f-0c2424879f52, localEntityId:https://idp-dev.cardiff.ac.uk/idp/shibboleth, peerEntityId:https://shib-sp-dev.cf.ac.uk/shibboleth, localId:[redacted], principalName:[redacted], peerProvidedId:null, creationTime:2009-06-25 14:45:00.807, deactivationTime:null, }
14:45:00.823 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316] - Resolved attribute eduPersonTargetedID.old containing 1 values
14:45:00.978 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:294] - Resolving attribute eduPersonTargetedID for principal [redacted]
14:45:01.016 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:316] - Resolved attribute eduPersonTargetedID containing 1 values
14:45:01.029 - DEBUG [edu.internet2.middleware.shibboleth.common.attribute.resolver.provider.ShibbolethAttributeResolver:138] - shibboleth.AttributeResolver resolved, for principal [redacted], the attributes: [eduPersonScopedAffiliation, eduPersonEntitlement, commonName, eduPersonPrincipalName, givenName, eduPersonTargetedID.old, uid, surname, organizationalUnit, transientId, eduPersonTargetedID, email, telephoneNumber, eduPersonAffiliation]