It could just be a hiccough in the logging but this looks odd:

> 11:10:29.022 - DEBUG [edu.vt.middleware.ldap.Ldap:550] -   dn = 
> dc=Strat-Col,dc=stratford,dc=ac,dc=uk

What does your login.conf look like?  In particular what does

base="XXXX"

 point to?

I would expect to say something like

base="CN=Users,DC=Strat-Col,dc=stratford,dc=ac,dc=uk"

Rod

----- Original Message ----- 
From: "SUBSCRIBE UKFEDERATION-DISCUSS Baljit" <[log in to unmask]>
To: <[log in to unmask]>
Sent: Tuesday, July 14, 2009 11:34 AM
Subject: Authentication Failure


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.
>
>
>
>