Hi,
I'm setting up my first IDP. When I test with testshib I get an authentication
failure. I've attached relevant sections of the IDP process log and security
log. Has anyone come across this problem and solved it?
Regards,
B Chima
Systems Analyst
Computing Services
Stratford upon Avon College
IDP process log
11:10:17.526 - INFO [Shibboleth-Access:72] - 20090714T101017Z|172.16.101.168|vm-idp.strat-col.stratford.ac.uk:443|/profile/SAML2/Redirect/SSO|
11:10:17.536 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:85] - shibboleth.HandlerManager: Looking up profile handler for request path: /SAML2/Redirect/SSO
11:10:17.536 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.IdPProfileHandlerManager:93] - shibboleth.HandlerManager: Located profile handler of the following type for the request path: edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler
11:10:17.536 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:144] - Incoming request does not contain a login context, processing as first leg of request
11:10:17.536 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:288] - Decoding message with decoder binding urn:oasis:names:tc:SAML:2.0:bindings:HTTP-Redirect
11:10:17.536 - DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:72] - Beginning to decode message from inbound transport of type: org.opensaml.ws.transport.http.HttpServletRequestAdapter
11:10:17.536 - DEBUG [org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder:93] - Decoded RelayState: null
11:10:17.536 - DEBUG [org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder:130] - Base64 decoding and inflating SAML message
11:10:17.536 - DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:140] - Parsing message stream into DOM document
11:10:17.536 - DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:150] - Unmarshalling message DOM
11:10:17.536 - DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:162] - Message succesfully unmarshalled
11:10:17.536 - DEBUG [org.opensaml.saml2.binding.decoding.HTTPRedirectDeflateDecoder:108] - Decoded SAML message
11:10:17.536 - DEBUG [org.opensaml.saml2.binding.decoding.BaseSAML2MessageDecoder:111] - Extracting ID, issuer and issue instant from request
11:10:17.536 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:194] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
11:10:17.536 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
11:10:17.536 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:77] - Metadata document does not contain an EntityDescriptor with the ID https://sp.testshib.org/shibboleth-sp
11:10:17.536 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:194] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
11:10:17.536 - DEBUG [org.opensaml.saml2.metadata.provider.HTTPMetadataProvider:200] - Cached metadata is stale, refreshing
11:10:17.536 - DEBUG [org.opensaml.saml2.metadata.provider.HTTPMetadataProvider:228] - Refreshing cache of metadata from URL http://www.testshib.org/metadata/testshib-providers.xml, max cache duration set to 2880 seconds
11:10:17.536 - DEBUG [org.opensaml.saml2.metadata.provider.HTTPMetadataProvider:271] - Fetching metadata document from remote server
11:10:18.257 - DEBUG [org.opensaml.saml2.metadata.provider.HTTPMetadataProvider:284] - Unmarshalled metadata from remote server
11:10:18.257 - DEBUG [org.opensaml.saml2.metadata.provider.FileBackedHTTPMetadataProvider:106] - Writting retrieved metadata to backup file D:\Shibboleth\idp\metadata\testshib.xml
11:10:18.257 - DEBUG [org.opensaml.saml2.metadata.provider.FileBackedHTTPMetadataProvider:158] - Converting DOM to a string
11:10:18.267 - DEBUG [org.opensaml.saml2.metadata.provider.HTTPMetadataProvider:233] - Calculating expiration time
11:10:18.267 - DEBUG [org.opensaml.saml2.metadata.provider.HTTPMetadataProvider:236] - Metadata cache expires on 2009-07-14T11:58:18.267+01:00
11:10:18.267 - INFO [org.opensaml.security.MetadataCredentialResolver:450] - Credential cache cleared
11:10:18.267 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:797] - Write lock over cache acquired
11:10:18.267 - INFO [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:802] - PKIX validation info cache cleared
11:10:18.267 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:805] - Write lock over cache released
11:10:18.267 - INFO [org.opensaml.security.MetadataCredentialResolver:450] - Credential cache cleared
11:10:18.267 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:797] - Write lock over cache acquired
11:10:18.267 - INFO [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:802] - PKIX validation info cache cleared
11:10:18.267 - DEBUG [edu.internet2.middleware.shibboleth.common.security.MetadataPKIXValidationInformationResolver:805] - Write lock over cache released
11:10:18.277 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
11:10:18.277 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:126] - Looking up relying party configuration for https://sp.testshib.org/shibboleth-sp
11:10:18.277 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:132] - No custom relying party configuration found for https://sp.testshib.org/shibboleth-sp, looking up configuration based on metadata groups.
11:10:18.277 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:194] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
11:10:18.277 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
11:10:18.277 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:77] - Metadata document does not contain an EntityDescriptor with the ID https://sp.testshib.org/shibboleth-sp
11:10:18.277 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:194] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
11:10:18.277 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
11:10:18.277 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:155] - No custom or group-based relying party configuration found for https://sp.testshib.org/shibboleth-sp. Using default relying party configuration.
11:10:18.277 - DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:82] - Evaluating security policy of type 'edu.internet2.middleware.shibboleth.common.security.ShibbolethSecurityPolicy' for decoded message
11:10:18.277 - DEBUG [org.opensaml.util.storage.ReplayCache:91] - Attempting to acquire lock for replay cache check
11:10:18.277 - DEBUG [org.opensaml.util.storage.ReplayCache:93] - Lock acquired
11:10:18.277 - DEBUG [org.opensaml.util.storage.ReplayCache:104] - Message ID _97e2c007f4c34f50726a820b67b5172a was not a replay
11:10:18.277 - DEBUG [org.opensaml.util.storage.ReplayCache:131] - Writing message ID https://sp.testshib.org/shibboleth-sp_97e2c007f4c34f50726a820b67b5172a to replay cache with expiration time 2009-07-14T11:15:18.277+01:00
11:10:18.277 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:194] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
11:10:18.277 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
11:10:18.277 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:77] - Metadata document does not contain an EntityDescriptor with the ID https://sp.testshib.org/shibboleth-sp
11:10:18.277 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:194] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
11:10:18.277 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
11:10:18.277 - DEBUG [org.opensaml.saml2.binding.security.SAML2AuthnRequestsSignedRule:91] - SPSSODescriptor for entity ID 'https://sp.testshib.org/shibboleth-sp' does not require AuthnRequests to be signed
11:10:18.277 - INFO [org.opensaml.common.binding.security.SAMLProtocolMessageXMLSignatureSecurityPolicyRule:99] - SAML protocol message was not signed, skipping XML signature processing
11:10:18.277 - DEBUG [org.opensaml.common.binding.security.BaseSAMLSimpleSignatureSecurityPolicyRule:63] - Evaluating simple signature rule of type: org.opensaml.saml2.binding.security.SAML2HTTPRedirectDeflateSignatureRule
11:10:18.277 - DEBUG [org.opensaml.common.binding.security.BaseSAMLSimpleSignatureSecurityPolicyRule:86] - HTTP request was not signed via simple signature mechanism, skipping
11:10:18.277 - DEBUG [org.opensaml.common.binding.security.BaseSAMLSimpleSignatureSecurityPolicyRule:63] - Evaluating simple signature rule of type: org.opensaml.saml2.binding.security.SAML2HTTPPostSimpleSignRule
11:10:18.277 - DEBUG [org.opensaml.common.binding.security.BaseSAMLSimpleSignatureSecurityPolicyRule:80] - Rule can not handle this request, skipping processing
11:10:18.277 - INFO [org.opensaml.ws.transport.http.HttpServletRequestAdapter:129] - Wrapped HTTP servlet request did not contain a client certificate
11:10:18.277 - INFO [org.opensaml.ws.security.provider.ClientCertAuthRule:97] - Inbound message transport did not contain a peer credential, skipping client certificate authentication
11:10:18.277 - DEBUG [org.opensaml.ws.message.decoder.BaseMessageDecoder:94] - Successfully decoded message.
11:10:18.277 - DEBUG [PROTOCOL_MESSAGE:96] -
<?xml version="1.0" encoding="UTF-8"?><samlp:AuthnRequest xmlns:samlp="urn:oasis:names:tc:SAML:2.0:protocol" AssertionConsumerServiceURL="https://sp.testshib.org/Shibboleth.sso/SAML2/POST" Destination="https://vm-idp.strat-col.stratford.ac.uk/idp/profile/SAML2/Redirect/SSO" ID="_97e2c007f4c34f50726a820b67b5172a" IssueInstant="2009-07-14T10:10:17Z" ProtocolBinding="urn:oasis:names:tc:SAML:2.0:bindings:HTTP-POST" Version="2.0">
<saml:Issuer xmlns:saml="urn:oasis:names:tc:SAML:2.0:assertion">https://sp.testshib.org/shibboleth-sp</saml:Issuer>
<samlp:NameIDPolicy AllowCreate="1"/>
</samlp:AuthnRequest>
11:10:18.277 - DEBUG [org.opensaml.common.binding.decoding.BaseSAMLMessageDecoder:180] - Checking SAML message intended destination endpoint against receiver endpoint
11:10:18.277 - DEBUG [org.opensaml.common.binding.decoding.BaseSAMLMessageDecoder:199] - Intended message destination endpoint: https://vm-idp.strat-col.stratford.ac.uk/idp/profile/SAML2/Redirect/SSO
11:10:18.277 - DEBUG [org.opensaml.common.binding.decoding.BaseSAMLMessageDecoder:200] - Actual message receiver endpoint: https://vm-idp.strat-col.stratford.ac.uk/idp/profile/SAML2/Redirect/SSO
11:10:18.277 - DEBUG [org.opensaml.common.binding.decoding.BaseSAMLMessageDecoder:208] - SAML message intended destination endpoint matched recipient endpoint
11:10:18.287 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:307] - Decoded request
11:10:18.287 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:194] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
11:10:18.287 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
11:10:18.287 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:77] - Metadata document does not contain an EntityDescriptor with the ID https://sp.testshib.org/shibboleth-sp
11:10:18.287 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:194] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
11:10:18.287 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
11:10:18.287 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:126] - Looking up relying party configuration for https://sp.testshib.org/shibboleth-sp
11:10:18.287 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:132] - No custom relying party configuration found for https://sp.testshib.org/shibboleth-sp, looking up configuration based on metadata groups.
11:10:18.287 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:194] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
11:10:18.287 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
11:10:18.287 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:77] - Metadata document does not contain an EntityDescriptor with the ID https://sp.testshib.org/shibboleth-sp
11:10:18.287 - DEBUG [org.opensaml.saml2.metadata.provider.ChainingMetadataProvider:194] - Checking child metadata provider for entity descriptor with entity ID: https://sp.testshib.org/shibboleth-sp
11:10:18.287 - DEBUG [org.opensaml.saml2.metadata.provider.AbstractMetadataProvider:206] - Searching for entity descriptor with an entity ID of https://sp.testshib.org/shibboleth-sp
11:10:18.287 - DEBUG [edu.internet2.middleware.shibboleth.common.relyingparty.provider.SAMLMDRelyingPartyConfigurationManager:155] - No custom or group-based relying party configuration found for https://sp.testshib.org/shibboleth-sp. Using default relying party configuration.
11:10:18.287 - DEBUG [edu.internet2.middleware.shibboleth.idp.profile.saml2.SSOProfileHandler:180] - Creating login context and transferring control to authentication engine
11:10:18.287 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:262] - Processing incoming request
11:10:18.287 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:292] - Beginning user authentication process.
11:10:18.287 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:351] - Filtering configured login handlers by requested athentication methods.
11:10:18.287 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:352] - Configured LoginHandlers: {urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler@161100c, urn:oasis:names:tc:SAML:2.0:ac:classes:PreviousSession=edu.internet2.middleware.shibboleth.idp.authn.provider.PreviousSessionLoginHandler@1649b1a}
11:10:18.287 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:353] - Requested authentication methods: org.opensaml.xml.util.LazyList@645ccb
11:10:18.287 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:300] - Possible authentication handlers for this request: {urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler@161100c, urn:oasis:names:tc:SAML:2.0:ac:classes:PreviousSession=edu.internet2.middleware.shibboleth.idp.authn.provider.PreviousSessionLoginHandler@1649b1a}
11:10:18.287 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:313] - Possible authentication handlers after filtering: {urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport=edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler@161100c, urn:oasis:names:tc:SAML:2.0:ac:classes:PreviousSession=edu.internet2.middleware.shibboleth.idp.authn.provider.PreviousSessionLoginHandler@1649b1a}
11:10:18.287 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:326] - Authenticating user with login handler of type edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler
11:10:18.287 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginHandler:75] - Redirecting to https://vm-idp.strat-col.stratford.ac.uk:443/idp/Authn/UserPassword
11:10:18.337 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:142] - Redirecting to login page /login.jsp
11:10:29.022 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:163] - Attempting to authenticate user testbc
11:10:29.022 - DEBUG [edu.vt.middleware.ldap.LdapProperties:299] - edu.vt.middleware.ldap.auth.userField = samAccountName
11:10:29.022 - DEBUG [edu.vt.middleware.ldap.LdapProperties:299] - edu.vt.middleware.ldap.auth.subtreeSearch = true
11:10:29.022 - DEBUG [edu.vt.middleware.ldap.Authenticator:143] - Looking up DN from userfield and base
11:10:29.022 - DEBUG [edu.vt.middleware.ldap.Ldap:549] - Search with the following parameters:
11:10:29.022 - DEBUG [edu.vt.middleware.ldap.Ldap:550] - dn = dc=Strat-Col,dc=stratford,dc=ac,dc=uk
11:10:29.022 - DEBUG [edu.vt.middleware.ldap.Ldap:551] - filter = (samAccountName=testbc)
11:10:29.022 - DEBUG [edu.vt.middleware.ldap.Ldap:552] - filterArgs =
11:10:29.032 - DEBUG [edu.vt.middleware.ldap.Ldap:554] - none
11:10:29.032 - DEBUG [edu.vt.middleware.ldap.Ldap:558] - retAttrs =
11:10:29.032 - DEBUG [edu.vt.middleware.ldap.Ldap:562] - []
11:10:29.032 - DEBUG [edu.vt.middleware.ldap.Ldap:1538] - Bind with the following parameters:
11:10:29.032 - DEBUG [edu.vt.middleware.ldap.Ldap:1539] - dn = cn=famshib,ou=ServiceAccounts,ou=UserAccounts,ou=MainCampus,dc=Strat-Col,dc=stratford,dc=ac,dc=uk
11:10:29.032 - DEBUG [edu.vt.middleware.ldap.Ldap:1543] - credential = <suppressed>
11:10:29.042 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:192] - User authentication for [testbc] failed
11:10:29.042 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:142] - Redirecting to login page /login.jsp
Security log on DC
Event Type: Success Audit
Event Source: Security
Event Category: Account Logon
Event ID: 680
Date: 14/07/2009
Time: 11:10:30
User: STRAT-COL\famshib
Computer: VM-AD-02
Description:
Logon attempt by: MICROSOFT_AUTHENTICATION_PACKAGE_V1_0
Logon account: famshib
Source Workstation: VM-AD-02
Error Code: 0x0
For more information, see Help and Support Center at http://go.microsoft.com/fwlink/events.asp.
Event Type: Success Audit
Event Source: Security
Event Category: Logon/Logoff
Event ID: 552
Date: 14/07/2009
Time: 11:10:30
User: NT AUTHORITY\SYSTEM
Computer: VM-AD-02
Description:
Logon attempt using explicit credentials:
Logged on user:
User Name: VM-AD-02$
Domain: STRAT-COL
Logon ID: (0x0,0x3E7)
Logon GUID: -
User whose credentials were used:
Target User Name: famshib
Target Domain: STRAT-COL
Target Logon GUID: -
Target Server Name: localhost
Target Server Info: localhost
Caller Process ID: 400
Source Network Address: 172.26.100.17
Source Port: 1734
For more information, see Help and Support Center at http://go.microsoft.com/fwlink/events.asp.
Event Type: Success Audit
Event Source: Security
Event Category: Logon/Logoff
Event ID: 540
Date: 14/07/2009
Time: 11:10:30
User: STRAT-COL\famshib
Computer: VM-AD-02
Description:
Successful Network Logon:
User Name: famshib
Domain: STRAT-COL
Logon ID: (0x0,0x23E05A)
Logon Type: 3
Logon Process: Advapi
Authentication Package: Negotiate
Workstation Name: VM-AD-02
Logon GUID: -
Caller User Name: VM-AD-02$
Caller Domain: STRAT-COL
Caller Logon ID: (0x0,0x3E7)
Caller Process ID: 400
Transited Services: -
Source Network Address: 172.26.100.17
Source Port: 1734
For more information, see Help and Support Center at http://go.microsoft.com/fwlink/events.asp.
|
