CAS 5.0.0RC1 - MFA webflow not found
166 views
Skip to first unread message
Philippe MARASSE
Sep 16, 2016, 10:57:46 AM9/16/16
to cas-...@apereo.org
Hello,
I'm trying to trigger MFA (with yubikey), on a service access. Triggering seems to work but mfa-yubikey webflow is not found ??
Extract from logs :
2016-09-16 16:28:03,438 DEBUG [org.springframework.webflow.engine.builder.DefaultFlowHolder] - <Assembling the flow for the first time>
2016-09-16 16:28:04,503 DEBUG [org.springframework.webflow.definition.registry.FlowDefinitionRegistryImpl] - <Registering flow definition 'URL [jar:file:/var/tomcat/inst2/webapps/cas/WEB-INF/lib/cas-server-support-yubikey-5.0.0.RC1.jar!/webflow/mfa-yubikey/mfa-yubikey-webflow.xml]' under id 'mfa-yubikey'>
2016-09-16 16:28:08,806 INFO [org.apereo.cas.configuration.CasConfigurationRebinder] - <Reloaded CAS configuration cas-org.apereo.cas.configuration.CasConfigurationProperties>
...
2016-09-16 16:28:41,259 INFO [org.ldaptive.auth.Authenticator] - <Authentication succeeded for dn: uid=myuser,ou=users,dc=example,dc=com>
2016-09-16 16:28:41,267 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <LdapAuthenticationHandler successfully authenticated myuser>
2016-09-16 16:28:41,299 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Authenticated myuser with credentials [myuser].>
2016-09-16 16:28:41,533 WARN [org.apereo.cas.web.flow.resolver.impl.RegisteredServiceAuthenticationPolicyWebflowEventResolver] - <Transition definition cannot be found for event [mfa-yubikey]>
2016-09-16 16:28:41,538 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.AuthenticationViaFormAction@b553; result = authenticationFailure>
Is login-webflow.xml needing modifications (documentation does not mention this) ?
Regards.
I'm trying to trigger MFA (with yubikey), on a service access. Triggering seems to work but mfa-yubikey webflow is not found ??
Extract from logs :
2016-09-16 16:28:03,438 DEBUG [org.springframework.webflow.engine.builder.DefaultFlowHolder] - <Assembling the flow for the first time>
2016-09-16 16:28:04,503 DEBUG [org.springframework.webflow.definition.registry.FlowDefinitionRegistryImpl] - <Registering flow definition 'URL [jar:file:/var/tomcat/inst2/webapps/cas/WEB-INF/lib/cas-server-support-yubikey-5.0.0.RC1.jar!/webflow/mfa-yubikey/mfa-yubikey-webflow.xml]' under id 'mfa-yubikey'>
2016-09-16 16:28:08,806 INFO [org.apereo.cas.configuration.CasConfigurationRebinder] - <Reloaded CAS configuration cas-org.apereo.cas.configuration.CasConfigurationProperties>
...
2016-09-16 16:28:41,259 INFO [org.ldaptive.auth.Authenticator] - <Authentication succeeded for dn: uid=myuser,ou=users,dc=example,dc=com>
2016-09-16 16:28:41,267 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <LdapAuthenticationHandler successfully authenticated myuser>
2016-09-16 16:28:41,299 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Authenticated myuser with credentials [myuser].>
2016-09-16 16:28:41,533 WARN [org.apereo.cas.web.flow.resolver.impl.RegisteredServiceAuthenticationPolicyWebflowEventResolver] - <Transition definition cannot be found for event [mfa-yubikey]>
2016-09-16 16:28:41,538 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.AuthenticationViaFormAction@b553; result = authenticationFailure>
Is login-webflow.xml needing modifications (documentation does not mention this) ?
Regards.
-- Philippe MARASSE Responsable pôle Infrastructures - DSIO Centre Hospitalier Henri Laborit CS 10587 - 370 avenue Jacques Cœur 86021 Poitiers Cedex Tel : 05.49.44.57.19
Philippe MARASSE
Sep 20, 2016, 3:38:12 AM9/20/16
to cas-...@apereo.org
Hello,
I've rolled back to simple LDAP Authentication + Yubikey, my service definition (generated via cas-management webapp) is :
{
@class: org.apereo.cas.services.RegexRegisteredService
serviceId: https?://myserver.example.com/testcas/cas5v3.php
name: test mfa
id: 3139139547012322
description: Test MFA Yubikey
evaluationOrder: 1
logoutType: NONE
attributeReleasePolicy:
{
@class: org.apereo.cas.services.ReturnAllAttributeReleasePolicy
principalAttributesRepository:
{
@class: org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository
expiration: 2
timeUnit: HOURS
}
authorizedToReleaseCredentialPassword: false
authorizedToReleaseProxyGrantingTicket: false
}
multifactorPolicy:
{
@class: org.apereo.cas.services.DefaultRegisteredServiceMultifactorPolicy
multifactorAuthenticationProviders:
[
java.util.HashSet
[
mfa-yubikey
]
]
failureMode: CLOSED
}
accessStrategy:
{
@class: org.apereo.cas.services.DefaultRegisteredServiceAccessStrategy
enabled: true
ssoEnabled: true
requireAllAttributes: true
caseInsensitive: false
}
}
Yubikey web-flow seems to be registered :
2016-09-20 09:20:09,895 DEBUG [org.springframework.webflow.definition.registry.FlowDefinitionRegistryImpl] - <Registering flow definition 'URL [jar:file:/var/tomcat/inst2/webapps/cas/WEB-INF/lib/cas-server-support-yubikey-5.0.0.RC1.jar!/webflow/mfa-yubikey/mfa-yubikey-webflow.xml]' under id 'mfa-yubikey'>
...
2016-09-20 09:20:36,003 WARN [org.apereo.cas.web.flow.resolver.impl.RegisteredServiceAuthenticationPolicyWebflowEventResolver] - <Transition definition cannot be found for event [mfa-yubikey]>
In MFA wiki page ( https://apereo.github.io/cas/development/installation/Configuring-Multifactor-Authentication.html#yubikey ), there's a mention of "id" field, but I didn't find any reference in my configuration files.
Regards.
I've rolled back to simple LDAP Authentication + Yubikey, my service definition (generated via cas-management webapp) is :
{
@class: org.apereo.cas.services.RegexRegisteredService
serviceId: https?://myserver.example.com/testcas/cas5v3.php
name: test mfa
id: 3139139547012322
description: Test MFA Yubikey
evaluationOrder: 1
logoutType: NONE
attributeReleasePolicy:
{
@class: org.apereo.cas.services.ReturnAllAttributeReleasePolicy
principalAttributesRepository:
{
@class: org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository
expiration: 2
timeUnit: HOURS
}
authorizedToReleaseCredentialPassword: false
authorizedToReleaseProxyGrantingTicket: false
}
multifactorPolicy:
{
@class: org.apereo.cas.services.DefaultRegisteredServiceMultifactorPolicy
multifactorAuthenticationProviders:
[
java.util.HashSet
[
mfa-yubikey
]
]
failureMode: CLOSED
}
accessStrategy:
{
@class: org.apereo.cas.services.DefaultRegisteredServiceAccessStrategy
enabled: true
ssoEnabled: true
requireAllAttributes: true
caseInsensitive: false
}
}
Yubikey web-flow seems to be registered :
2016-09-20 09:20:09,895 DEBUG [org.springframework.webflow.definition.registry.FlowDefinitionRegistryImpl] - <Registering flow definition 'URL [jar:file:/var/tomcat/inst2/webapps/cas/WEB-INF/lib/cas-server-support-yubikey-5.0.0.RC1.jar!/webflow/mfa-yubikey/mfa-yubikey-webflow.xml]' under id 'mfa-yubikey'>
...
2016-09-20 09:20:36,003 WARN [org.apereo.cas.web.flow.resolver.impl.RegisteredServiceAuthenticationPolicyWebflowEventResolver] - <Transition definition cannot be found for event [mfa-yubikey]>
In MFA wiki page ( https://apereo.github.io/cas/development/installation/Configuring-Multifactor-Authentication.html#yubikey ), there's a mention of "id" field, but I didn't find any reference in my configuration files.
Regards.
--
You received this message because you are subscribed to the Google Groups "CAS Community" group.
To unsubscribe from this group and stop receiving emails from it, send an email to cas-user+u...@apereo.org.
To post to this group, send email to cas-...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/cas-user/.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/dd99844e-7ea7-12e4-9872-323d46c2f8a9%40ch-poitiers.fr.
For more options, visit https://groups.google.com/a/apereo.org/d/optout.
Philippe MARASSE
Sep 22, 2016, 4:45:15 PM9/22/16
to cas-...@apereo.org
At last, it seems to trigger as expected with 5.0.0-RC3-SNAPSHOT (I
was using 5.0.0-RC1).
First test :
- Login form
- yubikey
=> it works as expected (login+password, then yubikey token, then logged to application)
Second test :
- SPNEGO
- yubikey
=> works oddly : my client service page uses phpCAS, on first pass I get an "Authentication Error, try again", If I click on "try again", then yubikey token is asked, and after validation, I'm logged to the application.
I suspect that transition on success after SPNEGO to be incorrect. It's hardcoded to CasWebflowConstants.TRANSITION_ID_SEND_TICKET_GRANTING_TICKET, but MFA shoud be inspected before sending TGC, shouldn't it ?
Here's the log, first pass :
2016-09-22 22:29:25,698 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <0 expired tickets removed.>
2016-09-22 22:29:25,698 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Finished ticket cleanup.>
2016-09-22 22:30:09,078 DEBUG [org.springframework.webflow.executor.FlowExecutorImpl] - <Resuming flow execution with key '6010b9af-cc40-4b75-8f87-da32571c10b9_ZXlKaGJHY2lPaUpJVXpVeE1pSjkuZFV4cFZTdFNRbFoxTDBneVdGbEZSMnBGVTBGSlVWbFhlbE5KVVdKMk1VbGxhRFZ3T1V0dVJuVnJWalZTZEhoek5EaDJOVEpVTlVORFZYQnhSaTlPUzBvM05FSXJOMkpMZWxWVFpVNHJkR3N4SzFCRFFuZzVkM1JuTkRsRGQwcE5aSGgwZEhWbVFrWjJOV3BvYlRka2QxcGhSbGxHTHk5cWRFWTVObTVNVm5reU9UVmFTMVZvU1hGUWIzTmpla1Y0VGpCeFN5OTRjRzlyV1VwT1ZYVjBUV3RSZDBwVVdtMDRlbHBwTVdOMWJIaGtjRUpQTDNaSlYxWldSVXBpUVZsRU5pdENlVEZTWW14TGVHVk5ha1JvT1daSGJWcG1TV04xZHpSdlkxVlNWalpJWjNCS01uaHBNM1ZxWTA1UFltZFZRMEp6V0cxeE16QmpSRVJDYVVkSlJVTlBXbmxZTjNsclVqTXhhMjlPUmtwUE1UTjVUR3BGY1RrdmExaFNWVWh1TDNGU1JrcFdlbkZ2WWxGWVdHRnBZMjk1T1VoRkt6SXdSbTEwZG5oclJucDJNekkwTm1aTk5rTldlRk5JYWl0SllrTlRhMlF2WVhWc2NrOVRSQ3RxVFZFNFJYWk5XRkJaZUZocFJEaDJlRFEwWTBkc01GSkhiakpYZVhKdU9IcG9ORzVzTWk5RU5tNVlSVkIzVEhSVGMwWktURmd3VG1GRldVZFBjMFZxUVZVM01IbzJUVTlCVUZSWldsUkVaVTk0WlVsVmJGaENMekJpYmpGcE5FcEZPVW81TDBkeE9YZzJWUzlFTXk5T1ZWWkpXblZsTUhSQ2RERkZXWFZEVkRSVlVWZEZSVEEzYVdvMWJVTkVVbWx3TlZsRE5uQmFPVTVFV1RkRVpYTklTV3BRYW5kUlRXRmpRWEZNVGs1YWNVNTNZbnA1TUZSSldFcFlhSGRHTW1WWE5TdDBlV0pNUjNKNE5FdHFPWGRTTjNveGFrcHBOR2t2VkhJclUzUndaamh3TTAxeUx6VktSRkpOY1Rodk0zRkRWSGgzT1ZkNU9XeEVWR1l5Y0dKaFN6bGhNM2t6Vm1ka01GWktVak5GT1VkaFFsQkVkRzFsZVZKc1pHUjFSR2cwUzNSdU1rSlFkV2RaYjBOQ1Z6TlBabTh5U1dkUVNteFJRbFJoYm5WV0swOTJOR1ZIYlhsSGExWndXR2hPY1RoQmNuRmxPVFZ1YmxaWGRWSmxkalpQVHpjMlRFaEJjbTk2Ykc1ME5FVnphRmhRYzJoTFNFRjFTbmhaV1dOall6SnFjbnBJYTFwTVlUaEpOSFF2T1ZaemNVMHZaM2xITmpOSVEyTkZUMFZDY25KaFpuSm9SbTB6WVZOUWJsSnBNaXRIY1VWbFNqRnBjbVoyWkdRd2NHUnljWGd5UjFoSmJYZDZTWFJ5YzNOMWRuUkhXVFJWVGl0MlRHcGhXVUkwUTBONVVsTk9hMUZJTnpNMGQxWlFkak54VG05WGIyRlFhRkZMVlRGRVVWWm5aVUkxTldGamNESnZNRFJxTDJOb2FWVmlaazlJY2tWa2RtcEhjRlJ3ZGtzd2RIcHFiRGxVZVZGc01tbERUQzl6WjNSRWNtSnlhSFE1U2pSelVVVkVTMUpJTmtGcVdXMUpTa2c0Ym1aNlFYZFVia3N3WmpoMVozTnVZVXBVUWpkb09TdEdOVk5CTTI5WmQxSnBaVXh6UjJ0WmNFcDNNV04zUW01elRWTTFVMDlQVjNrellubEdZMWhZWjNvdmNHMUVRME4zYm1NelJFNXVlR3hwZVhvMlMzb3ZNMUpYZFdkMVIxZzJWVzFrTWpadVFreHBLM0puZG5WYWNWSjFibWRoZGxBdlprSnlSMDAyY0RCcFJISjZaR0ZETm01dVZYWnNTV3h0TmtaU05rSkZhVWM0V0dGbGJGaHlTMll3TW1aS1ZreHZVazFwZWxKMVdsaG9ORWh1YjFNcmMzaFFPVzVyTmk5aUszSmhkMVJqV21aa2MwNURTa1ZwVGxkTFFuZEZlRlZ5YUVGUFUyNURVSFJMVUd4eFYxa3JNVVZtZVhwdU1IRTNRMWN4ZVVWbGVtaDNiRzR3WTJKcFpFMXpNQ3RWV0VOTFdYcFdibGt3UjJaRlNqTnBNakpoUTFkU05rZ3ZhbUZHVDNaSWNXUm1jRFV5YUVWclZVbENWbVF3VVU1R04zbHNXU3RDYkhGVlJWbG1WbmRwU1dSWWRuTm5aMVptY25oUldTc3pVVlJXTVhwUFZ6a3pkVVV6YzJsRlZWbDBUUzh5ZWxOblJXWTRXbTFLUkVSV1dIWkZjWEp5WnpkdVZrbFdSREJIYUVaQlJYZ3pMMlZvYzNCMmNURk9SeTk1WTJWeFl6aHRlbFZaVlhCdGJ6VkpVVFFyVWt4cFlVZEJNemQwUkdSQ2VXdzVhV1puYld0NU5tVjFjbGRpVEdOVlIyMDBTR0ZrU0hJNWJHSkdjMHQxVFRZMGRVcFNPVmRHUWpsNlJXdHdla040Tkc5eGRFcFlWMVZKU1hkWmFWVnJVRlJ2U0dWVFQzUTRaVWRsYkZkTFNWaFljRWRCWmxsQmF5dE1Oa3BYZVhkeE1UQjVZMGhFVmtnNVQwNWhTMWRQZVdRMUwxcGlkUzlGWlc0NFFUSk5PR1phT0doTFR6SldaMUppYW05eFJraFNTRk00WTFobWQyZ3plV0p6YmxObk5HUmxhRTQxWkhNemNVbFNaa3d4UWpoc2NITXdVMkZIUXk5MlQyOWlTMGhTY1hKaU1VdFFSa05OUzNsWFlqTk1aV2hVUW5rMk4zWm9MelIwTjBSaU5YRkhTbGhsWTJRNFN6UnlXbVZ3YlhVMFVqbFVZbU40WTFwNVMyTnVlRGN3YWxWMldteFpUMmN6VmtGM01uTmlUMk16TjNJd2JXcDJMMUZDUjJ4YVRsVXJSV3BWU1ZaQk1FMDJiekpyWnpCVFkxazVTMUpHZUZabE1YQXpUbE5sY2pCYVQzSldTRmxxZDFRNFkxcEtjVmxXYUdaMlNFZHhTVEJhVTFOWllYZHVXbGhQZHpkUll6aHdObXBFY2pjcmVqVmhWbGN6TVdKb00wZ3dlbXBQU205UWNtUlNZM0pxY1V4NGRHMDVLMUZ4ZVM5blVuaE9ZMEprTTBOUVYyVTBkVFJRZFdSVE1FUlJUVFJrTUhwYVZVcFZiRUV2VG5GM1Z6SklWblZyVkRaV2FsbHNSazV6TjB4Q1FXMTJZVTF1YVRWRVRsRjBkV052UWs5c2FHdFpOMlZzT1ZwbU1VcFRlSEpRWmtsNlRWQllUekkxVkROMk4wMVVLM1ZEUm1SdGFXbzRMMm96Tnk5NU1tYzBjemd5YUZGdFJqRXZURWxTVDJOaVNERTBkR2RTYlVocU1GVkZZekZDT1ZWWWFGbFhXWEFyVEVWUllrTllRMU5uTW5WeWNFUmFOblZvWmxoV1ZYRkJVWEpGZGxVelluVkhOQzgzVURsa2NGbHVRWGhhTHpReFNsRkNNMGR3TjNwcmQzazBjREZFZG1Sb2RHSkViMFZqUzFOeFVqVjVXVGxMS3pOTVUyWXdja1pUT0RkTE1TOXpOeXRhYm5kaFZHSjNhVWRSWW14NlEwWk9TbFZyUkdOak4xTTRZeTlwVm04ekwyRlZZMFJXTVRNclRGZGpSVUp6WkN0c1QwUlpOSEpHUkVRMGFFdzVaVmxzVlhkTU5WbHFWa000THpkcWVVaHlXVUpGUkZFMFIxVjRWbkY1TmpKMk1sVllNekV2UkhKTE1tMUVhQ3RwVURocFpYVnFVekpRY0haSU1HRTVkemhHYTIxNldXRjVXbFZrVkZCMGVUVktRbTVOUkcxSmFVRk5ja0kwYzJaUlpqTnBZbUZqV2xGTFVIZFRSQzk2Vlc5TFUwSnJOVXRZUmtKSE1tSk5aMjVDVDFGcGR6QTFjakpSZHpjM1UyODVRV3hHVVdwb1VHSm1iMlY0U2tOb1JFSjJkamx0T1ZOcFZDdEdkbTl6T0hKVVQyc3lNRnBaUWpWWFZGSkViemxVUVVkWWVXRklNekpRUVZoYVVTdDRSbXRFVUVwT1QwSllZekJFV1RsTlNIRjVNSFYxVFVSdlJqaGFhVEZLTWxrdmVFcExXVWxDU1UxNlprOVVWbGhNTlZRMVpGVTBhbmhOVnk5blZUWTFSbU16VTJRNUwyZHVNMmN6Wm14VVExWXJlbE52YjNWaVVXdG1lR0poYXpWVFluWkpkbFF3VEZaR01rZElZMWx1Y1ZwVVFuUlVSWEpyUWtoUmFVczVMeXRNVGtad09GRkZNa1JXWVcxcGJHOTVhVzlLYkVWNlREQjZLMHByY2tsSmNrSTViMkpUZHk5V1dHRkRTWFZEVTA1NFNERkVTV2hLUVhsNFZFVTRXR1J1UWt0NGNrWlZXbEJIUldObFFrUTFWSFV4VDNsdVdIbFdMMlpIYkdSSFRuSkhRa013UlZsMmEyMVlaMGxIZFdNMlpqTk5TVmxDVFRSU2VqSjRZbEprTTIwdlZ6RXZOR1pZTHpRemJHeFliSFJGY0hvNE5URmlkRzFJYWxZeVVFdEpkMFpHU1U1c2RuZzFhVmh1U1hVeE5rbHJOelZ1ZGpBMlpGVnlWbGRwWkhWRlVVa3lVRVpvWWk5VlVsTkxVMEZ4VW1oTmJrOVZVbVpxTUhOS1pGRmlNVXBMWTJKUkwybFZPVE5oYXl0dVdFSk5XVzFETjI5UGJFeHpWbEozTlRCYWIwWk5WelF5YTA5VWVsbHJlWFpPTVRCVVpVaGhNVXBqTTFoSk1tNXVSRWhXTVRSb1dqRkhORW94ZDBKNGFtdHhPR2hVUTNsNVMxVTBUREJSWmpZeVJEWjBUMk1yTVdGdmRVbG9RaTlpWkZOUmFtSlRLM3BXZFRBemJ6aFNXblJYVWtOWlFrcGtTMnBSZEZaVE0yYzNNMWh1YUhkaVIybHRZbGh6T0c0MldGVmxUalZLUzNsaFlXVlZOVVZpTkVKclQwazBRV05MVVd0UFdVTjBiRkZKV0d0dlNVcGtOMEpEU2pkeVRIQXdSMVIwU0ZkdE1YWkVTblZMY0ZOU2F6TnhlR3htU1VsMlFWaExhME15U1hkSk5IaHZaM0JIZUdoTmFXWlBNSEJsTlhsdU5FUnpLekV2V21ocmFtWjBSRmxXTDFocVRHTTFObmhYU2xJMFpWcGFaWEl6Vm5oVWRHeFRZME41Y1dkNlZVa3JLMVE0TkhwdE9EZEJkRWhQZG1RcmNqQlViVXR1UkVWb2QzbzBZV00yZURJeVJ6VnVlRW96TldoTlZteGphV1pMYUdJMWVUaDBOVTlzVmk5QlpqUTNkakpCWVZnck5GVnljWGx5U1ZRMllqaE9ZMElyWTI1QmVFa3hZMWxQYjBKS1YyeFhaVGx5VlRsUlNFcFplSHBZVUc1WmRrTTFWVTVEU0VZMVkwRXZSamRRZFV4VGVYRkVTR3BSTVhkb2FYRjJXV1pzZFcwelJDOWtZWEpJZHpaUVZuUnhTVUV5YmxKaVUzSXZRbEJvYVdGUlZYRmxVMjVSUjFReFFTOXVaVU5EVTBJNWFuTldUbGhrYzIxV2EzQlZWV2xtZDBSQk9FWmlOMlZOTVU1UmRYRkpXalYyY0dOV1IwWk5WSGhEYW1WR1VsSmxNMHQxVWl0RWJuQkZNMkZuWnpWeFVUQXpRM1pGUzNoU1ZIVlFkVzlDTkRGM2JqZ3djR3A2Y0hGQmNqZHBaaTlxT1VwTllYaFBXVEJEV2toT1JIcEtlREZhYjFrNFlVUk5RMEZRUjB4SGJrSnRTWG81Umpkc0x6WjBOSE51T0VNeWIxaG5SakF3YUdsVVRHVk5jSGxKVUVoTVdqRkpTRkpJYjFabWVFZFVXQzlUVnpSd1dEQlFZa0pqV2xGaFJYTlZWRVF6UkVvdmMxUkVOSFJFUkU5d2Vrd3ZaR1ZDY1VnM01uQlJWV1ZPVjA1U1lYSlJabFZOUTFWaFNtNHZlRkp2ZWpGdVoyMDNOMWxIV25SU1kzbElaMFZQU2poWVZVaGFiVGRGZFZWcGVETldlbmRXYVcwNWMzZGhZa2R5TWtwalFrWmtiM2hhWjBOMFMxTnhlWHBCVDJ4MVdqVktkVzFDTlVSVVQxbExRWGR1UTBGS09WcElTamgwYVVFMVpreDVTa2hTYWtKdGRGWlpNMVZUYkVGQ1NXTjZaVXRXUzBaNk5uaFRSa0pUTVVSVFZWRkVTMVphWkdaWVlYUnRWREZ3U2s5TWVXeFJiWFp6Tmxoc2VXbGxXbU5oZDIxUEwxUkhkbUZqV21zdk0xTTFOM0IxYzFSM1VDdDVRVTR4VEZCSFNraGFTRXAwYkhkMVZIZG5aVk1yWlcxdVNtc3hlbTVwVTJaM1lWRk1XbnBwTkd4SmJGWmlUMk4wVERCcVEwRTFkRlkwTjJFMlVTdGpPVWhEU1NzMGVtMVlNMWRPUjFKQ1VYaEtSRWN2T1ZKdGNITldkVzQzTlc4dlpIbE9iVlZ2VDJGMVJHaHFkbXd4Tm5GUlVXMTRWa2hqVlZObFN6WXdUek5xUzNSaWJFNUlXV0ZPYXk5NmFuWnNRekJ6Tnpkck5GUjFTV3R3YUZsMmRFRXhjM1V3Y2pVNWQyaGhiVzlsYWs5R1prRXlkMnRoVFZsTU5rMVJjbkpRY1c5SGMyeEhhbTFhZWtnclFXUnRTblJHUTJkMVZtNW9jRGhwWWtsbVNubFNZVzR3Y2xsS1QzRTFNRVI0WkZkaWNXNXBZamc1ZWpKVVR6TnRUbUY0YUVsdVIwTjZZVE14WTFJeWExSlhMM0p4VlZscE0xaFhMMnN6TlhKYU9IZFZXREpzU2pSNGJXVnRiVlZTWldWSGExWTJhWFEyVUVOM2NFWmplSFlyY0VWaVltWnRNMUpCYWxjdlltNXRNM2t2WWpSM1pqSm9RbkZFZVVkUmFpOWlMMFpVZVZGSldXdERTVGQ1V21sUlVtczkub08ybHRYRDd5MjhqdnlWYUZvb2wyYWhEV2xDcnE5Ql95X3d1c2tJMnNGWDBjM2k0WUlJZ3VGempRX2ZBTW9ValVuejVzR0g0eXROaDJlTURDcVdzc2c=>
2016-09-22 22:30:09,085 DEBUG [org.springframework.webflow.definition.registry.FlowDefinitionRegistryImpl] - <Getting FlowDefinition with id 'login'>
2016-09-22 22:30:09,085 DEBUG [org.springframework.webflow.definition.registry.FlowDefinitionRegistryImpl] - <Getting FlowDefinition with id 'mfa-yubikey'>
2016-09-22 22:30:09,085 DEBUG [org.springframework.webflow.engine.Flow] - <Restoring [FlowVariable@db6ca7 name = 'credential', valueFactory = [BeanFactoryVariableValueFactory@1a0b4be type = YubiKeyCredential]]>
2016-09-22 22:30:09,115 DEBUG [org.springframework.webflow.engine.ViewState] - <Rendering + [ServletMvcView@e83f9c view = org.thymeleaf.spring4.view.ThymeleafView@403fe0]>
2016-09-22 22:30:09,115 DEBUG [org.springframework.webflow.engine.ViewState] - < Flash scope = map[[empty]]>
2016-09-22 22:30:09,115 DEBUG [org.springframework.webflow.engine.ViewState] - < Messages = [DefaultMessageContext@11e713c sourceMessages = map[[null] -> list[[empty]], 'token' -> list[[Message@2a0a13 source = 'token', severity = ERROR, text = 'required on token']]]]>
2016-09-22 22:30:25,700 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <0 expired tickets removed.>
2016-09-22 22:30:25,700 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Finished ticket cleanup.>
2016-09-22 22:31:17,096 DEBUG [org.springframework.webflow.executor.FlowExecutorImpl] - <Launching new execution of flow 'login' with input map['service' -> 'https://testcas.example.com/philippe/eclipse/testcas/www/cas5v3.php']>
2016-09-22 22:31:17,097 DEBUG [org.springframework.webflow.definition.registry.FlowDefinitionRegistryImpl] - <Getting FlowDefinition with id 'login'>
2016-09-22 22:31:17,097 DEBUG [org.springframework.webflow.engine.Flow] - <Creating [FlowVariable@17f0abb name = 'credential', valueFactory = [BeanFactoryVariableValueFactory@7ad7ff type = UsernamePasswordCredential]]>
2016-09-22 22:31:17,099 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@12fb90f expression = initialFlowSetupAction, resultExpression = [null]]>
2016-09-22 22:31:17,100 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,100 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.InitialFlowSetupAction@2c1fd6>
2016-09-22 22:31:17,101 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.InitialFlowSetupAction@2c1fd6; result = success>
2016-09-22 22:31:17,102 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,103 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@12fb90f expression = initialFlowSetupAction, resultExpression = [null]]; result = success>
2016-09-22 22:31:17,103 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'initialAuthenticationRequestValidationCheck' of flow 'login'>
2016-09-22 22:31:17,103 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@1c95611 expression = initialAuthenticationRequestValidationAction, resultExpression = [null]]>
2016-09-22 22:31:17,104 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,104 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.InitialAuthenticationRequestValidationAction@18b8f92>
2016-09-22 22:31:17,104 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.InitialAuthenticationRequestValidationAction@18b8f92; result = success>
2016-09-22 22:31:17,105 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,105 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@1c95611 expression = initialAuthenticationRequestValidationAction, resultExpression = [null]]; result = success>
2016-09-22 22:31:17,105 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@14a857c on = success, to = ticketGrantingTicketCheck]>
2016-09-22 22:31:17,105 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'initialAuthenticationRequestValidationCheck'>
2016-09-22 22:31:17,106 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'ticketGrantingTicketCheck' of flow 'login'>
2016-09-22 22:31:17,106 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@12e9394 expression = ticketGrantingTicketCheckAction, resultExpression = [null]]>
2016-09-22 22:31:17,106 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,106 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.TicketGrantingTicketCheckAction@21f96a>
2016-09-22 22:31:17,107 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.TicketGrantingTicketCheckAction@21f96a; result = notExists>
2016-09-22 22:31:17,107 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,107 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@12e9394 expression = ticketGrantingTicketCheckAction, resultExpression = [null]]; result = notExists>
2016-09-22 22:31:17,107 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@135045f on = notExists, to = gatewayRequestCheck]>
2016-09-22 22:31:17,108 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'ticketGrantingTicketCheck'>
2016-09-22 22:31:17,108 DEBUG [org.springframework.webflow.engine.DecisionState] - <Entering state 'gatewayRequestCheck' of flow 'login'>
2016-09-22 22:31:17,108 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@138f996 on = *, to = serviceAuthorizationCheck]>
2016-09-22 22:31:17,109 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'gatewayRequestCheck'>
2016-09-22 22:31:17,109 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'serviceAuthorizationCheck' of flow 'login'>
2016-09-22 22:31:17,109 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@16557fe expression = serviceAuthorizationCheck, resultExpression = [null]]>
2016-09-22 22:31:17,109 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.ServiceAuthorizationCheck@41dba0>
2016-09-22 22:31:17,111 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.ServiceAuthorizationCheck@41dba0; result = success>
2016-09-22 22:31:17,112 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@16557fe expression = serviceAuthorizationCheck, resultExpression = [null]]; result = success>
2016-09-22 22:31:17,112 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@1950931 on = *, to = initializeLoginForm]>
2016-09-22 22:31:17,112 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'serviceAuthorizationCheck'>
2016-09-22 22:31:17,113 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'initializeLoginForm' of flow 'login'>
2016-09-22 22:31:17,113 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@1ce528f expression = initializeLoginAction, resultExpression = [null]]>
2016-09-22 22:31:17,113 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,113 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.InitializeLoginAction@10826f8>
2016-09-22 22:31:17,113 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.InitializeLoginAction@10826f8; result = success>
2016-09-22 22:31:17,114 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,114 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@1ce528f expression = initializeLoginAction, resultExpression = [null]]; result = success>
2016-09-22 22:31:17,114 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@1b6e8e9 on = success, to = clientIp]>
2016-09-22 22:31:17,114 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'initializeLoginForm'>
2016-09-22 22:31:17,115 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'clientIp' of flow 'login'>
2016-09-22 22:31:17,115 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@5f8386 expression = ipBasedDispatcher, resultExpression = [null]]>
2016-09-22 22:31:17,115 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,115 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing fr.chpoitiers.cas.web.flow.NetworkBasedClientAction@d92576>
2016-09-22 22:31:17,116 DEBUG [fr.chpoitiers.cas.web.flow.NetworkBasedClientAction] - <Read Ip from request : 172.18.3.6 returning : interne>
2016-09-22 22:31:17,116 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing fr.chpoitiers.cas.web.flow.NetworkBasedClientAction@d92576; result = interne>
2016-09-22 22:31:17,117 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,117 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@5f8386 expression = ipBasedDispatcher, resultExpression = [null]]; result = interne>
2016-09-22 22:31:17,117 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@160ce7d on = interne, to = startSpnegoAuthenticate]>
2016-09-22 22:31:17,117 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'clientIp'>
2016-09-22 22:31:17,118 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'startSpnegoAuthenticate' of flow 'login'>
2016-09-22 22:31:17,118 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@75b2f4 expression = negociateSpnego, resultExpression = [null]]>
2016-09-22 22:31:17,118 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,119 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.SpnegoNegociateCredentialsAction@1623aa0>
2016-09-22 22:31:17,119 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.SpnegoNegociateCredentialsAction@1623aa0; result = negotiate>
2016-09-22 22:31:17,119 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,119 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@75b2f4 expression = negociateSpnego, resultExpression = [null]]; result = negotiate>
2016-09-22 22:31:17,120 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@82e673 on = negotiate, to = casSpnegoNegotiateView]>
2016-09-22 22:31:17,120 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'startSpnegoAuthenticate'>
2016-09-22 22:31:17,120 DEBUG [org.springframework.webflow.engine.EndState] - <Entering state 'casSpnegoNegotiateView' of flow 'login'>
2016-09-22 22:31:17,120 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.springframework.webflow.action.ViewFactoryActionAdapter@bf1356>
2016-09-22 22:31:17,234 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.springframework.webflow.action.ViewFactoryActionAdapter@bf1356; result = success>
2016-09-22 22:31:17,234 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,234 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,234 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,234 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,234 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,234 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,234 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,431 DEBUG [org.springframework.webflow.executor.FlowExecutorImpl] - <Launching new execution of flow 'login' with input map['service' -> 'https://testcas.example.com/philippe/eclipse/testcas/www/cas5v3.php']>
2016-09-22 22:31:17,431 DEBUG [org.springframework.webflow.definition.registry.FlowDefinitionRegistryImpl] - <Getting FlowDefinition with id 'login'>
2016-09-22 22:31:17,431 DEBUG [org.springframework.webflow.engine.Flow] - <Creating [FlowVariable@17f0abb name = 'credential', valueFactory = [BeanFactoryVariableValueFactory@7ad7ff type = UsernamePasswordCredential]]>
2016-09-22 22:31:17,432 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@12fb90f expression = initialFlowSetupAction, resultExpression = [null]]>
2016-09-22 22:31:17,433 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,433 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.InitialFlowSetupAction@2c1fd6>
2016-09-22 22:31:17,433 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.InitialFlowSetupAction@2c1fd6; result = success>
2016-09-22 22:31:17,433 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,433 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@12fb90f expression = initialFlowSetupAction, resultExpression = [null]]; result = success>
2016-09-22 22:31:17,433 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'initialAuthenticationRequestValidationCheck' of flow 'login'>
2016-09-22 22:31:17,433 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@1c95611 expression = initialAuthenticationRequestValidationAction, resultExpression = [null]]>
2016-09-22 22:31:17,433 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,433 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.InitialAuthenticationRequestValidationAction@18b8f92>
2016-09-22 22:31:17,434 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.InitialAuthenticationRequestValidationAction@18b8f92; result = success>
2016-09-22 22:31:17,434 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,434 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@1c95611 expression = initialAuthenticationRequestValidationAction, resultExpression = [null]]; result = success>
2016-09-22 22:31:17,437 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@14a857c on = success, to = ticketGrantingTicketCheck]>
2016-09-22 22:31:17,437 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'initialAuthenticationRequestValidationCheck'>
2016-09-22 22:31:17,438 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'ticketGrantingTicketCheck' of flow 'login'>
2016-09-22 22:31:17,438 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@12e9394 expression = ticketGrantingTicketCheckAction, resultExpression = [null]]>
2016-09-22 22:31:17,438 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,438 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.TicketGrantingTicketCheckAction@21f96a>
2016-09-22 22:31:17,439 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.TicketGrantingTicketCheckAction@21f96a; result = notExists>
2016-09-22 22:31:17,439 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,439 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@12e9394 expression = ticketGrantingTicketCheckAction, resultExpression = [null]]; result = notExists>
2016-09-22 22:31:17,440 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@135045f on = notExists, to = gatewayRequestCheck]>
2016-09-22 22:31:17,441 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'ticketGrantingTicketCheck'>
2016-09-22 22:31:17,441 DEBUG [org.springframework.webflow.engine.DecisionState] - <Entering state 'gatewayRequestCheck' of flow 'login'>
2016-09-22 22:31:17,442 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@138f996 on = *, to = serviceAuthorizationCheck]>
2016-09-22 22:31:17,442 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'gatewayRequestCheck'>
2016-09-22 22:31:17,442 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'serviceAuthorizationCheck' of flow 'login'>
2016-09-22 22:31:17,443 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@16557fe expression = serviceAuthorizationCheck, resultExpression = [null]]>
2016-09-22 22:31:17,443 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.ServiceAuthorizationCheck@41dba0>
2016-09-22 22:31:17,446 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.ServiceAuthorizationCheck@41dba0; result = success>
2016-09-22 22:31:17,446 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@16557fe expression = serviceAuthorizationCheck, resultExpression = [null]]; result = success>
2016-09-22 22:31:17,446 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@1950931 on = *, to = initializeLoginForm]>
2016-09-22 22:31:17,446 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'serviceAuthorizationCheck'>
2016-09-22 22:31:17,447 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'initializeLoginForm' of flow 'login'>
2016-09-22 22:31:17,447 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@1ce528f expression = initializeLoginAction, resultExpression = [null]]>
2016-09-22 22:31:17,447 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,447 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.InitializeLoginAction@10826f8>
2016-09-22 22:31:17,448 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.InitializeLoginAction@10826f8; result = success>
2016-09-22 22:31:17,448 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,448 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@1ce528f expression = initializeLoginAction, resultExpression = [null]]; result = success>
2016-09-22 22:31:17,448 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@1b6e8e9 on = success, to = clientIp]>
2016-09-22 22:31:17,449 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'initializeLoginForm'>
2016-09-22 22:31:17,449 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'clientIp' of flow 'login'>
2016-09-22 22:31:17,449 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@5f8386 expression = ipBasedDispatcher, resultExpression = [null]]>
2016-09-22 22:31:17,449 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,450 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing fr.chpoitiers.cas.web.flow.NetworkBasedClientAction@d92576>
2016-09-22 22:31:17,450 DEBUG [fr.chpoitiers.cas.web.flow.NetworkBasedClientAction] - <Read Ip from request : 172.18.3.6 returning : interne>
2016-09-22 22:31:17,450 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing fr.chpoitiers.cas.web.flow.NetworkBasedClientAction@d92576; result = interne>
2016-09-22 22:31:17,450 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,451 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@5f8386 expression = ipBasedDispatcher, resultExpression = [null]]; result = interne>
2016-09-22 22:31:17,451 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@160ce7d on = interne, to = startSpnegoAuthenticate]>
2016-09-22 22:31:17,451 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'clientIp'>
2016-09-22 22:31:17,451 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'startSpnegoAuthenticate' of flow 'login'>
2016-09-22 22:31:17,452 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@75b2f4 expression = negociateSpnego, resultExpression = [null]]>
2016-09-22 22:31:17,452 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,452 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.SpnegoNegociateCredentialsAction@1623aa0>
2016-09-22 22:31:17,453 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.SpnegoNegociateCredentialsAction@1623aa0; result = success>
2016-09-22 22:31:17,453 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,453 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@75b2f4 expression = negociateSpnego, resultExpression = [null]]; result = success>
2016-09-22 22:31:17,455 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@10a9ce1 on = success, to = spnego]>
2016-09-22 22:31:17,455 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'startSpnegoAuthenticate'>
2016-09-22 22:31:17,455 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'spnego' of flow 'login'>
2016-09-22 22:31:17,455 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@80e64 expression = spnego, resultExpression = [null]]>
2016-09-22 22:31:17,456 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,456 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.SpnegoCredentialsAction@1f9e7fa>
2016-09-22 22:31:17,458 DEBUG [org.apereo.cas.authentication.RegisteredServiceAuthenticationHandlerResolver] - <Authentication handlers used for this transaction are [org.apereo.cas.authentication.handler.support.HttpBasedServiceCredentialsAuthenticationHandler@29629e, org.apereo.cas.adaptors.yubikey.YubiKeyAuthenticationHandler@79962d, org.apereo.cas.support.spnego.authentication.handler.support.JcifsSpnegoAuthenticationHandler@3987f2, org.apereo.cas.authentication.LdapAuthenticationHandler@7e0895]>
2016-09-22 22:31:17,555 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <JcifsSpnegoAuthenticationHandler successfully authenticated testuser>
2016-09-22 22:31:17,582 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <org.apereo.cas.support.spnego.authentication.principal.SpnegoPrincipalResolver@1156153 resolved testuser from testuser>
2016-09-22 22:31:17,585 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Final principal resolved for this authentication event is testuser>
2016-09-22 22:31:17,596 DEBUG [org.apereo.cas.authentication.AnyAuthenticationPolicy] - <Authentication policy is satisfied having found at least one authentication transactions>
2016-09-22 22:31:17,597 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Authenticated testuser with credentials [testuser].>
2016-09-22 22:31:17,599 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Attribute map for testuser: {affiliation=groupMembership, cn=commonName, displayName=displayName, uid=uid, username=testuser}>
2016-09-22 22:31:17,601 INFO [org.apereo.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: testuser
WHAT: Supplied credentials: [testuser]
ACTION: AUTHENTICATION_SUCCESS
APPLICATION: CAS
WHEN: Thu Sep 22 22:31:17 CEST 2016
CLIENT IP ADDRESS: 172.18.3.6
SERVER IP ADDRESS: testcas.example.com
=============================================================
>
2016-09-22 22:31:17,604 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationTransactionManager] - <Successful authentication; Collecting authentication result [org.apereo.cas.authentication.DefaultAuthentication@e063db46]>
2016-09-22 22:31:17,606 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collecting authentication history based on [1] authentication events>
2016-09-22 22:31:17,607 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Evaluating authentication principal [testuser] for inclusion in result>
2016-09-22 22:31:17,608 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected principal attributes [{uid=uid, cn=commonName, affiliation=groupMembership, displayName=displayName, username=testuser}] for inclusion in this result for principal [testuser]>
2016-09-22 22:31:17,610 WARN [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Authentication attribute [samlAuthenticationStatementAuthMethod] has no value and is not collected>
2016-09-22 22:31:17,611 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [authenticationMethod] -> [JcifsSpnegoAuthenticationHandler]>
2016-09-22 22:31:17,613 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [successfulAuthenticationHandlers] -> [[JcifsSpnegoAuthenticationHandler]]>
2016-09-22 22:31:17,614 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Finalized authentication attributes [{authenticationMethod=JcifsSpnegoAuthenticationHandler, successfulAuthenticationHandlers=[JcifsSpnegoAuthenticationHandler]}] for inclusion in this authentication result>
2016-09-22 22:31:17,615 DEBUG [org.apereo.cas.authentication.DefaultPrincipalElectionStrategy] - <Nominated [testuser] as the primary principal>
2016-09-22 22:31:17,617 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Determined primary authentication principal to be [testuser]>
2016-09-22 22:31:17,618 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected authentication attributes for this result are [{authenticationMethod=JcifsSpnegoAuthenticationHandler, successfulAuthenticationHandlers=[JcifsSpnegoAuthenticationHandler]}]>
2016-09-22 22:31:17,619 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Authentication result commenced at [2016-09-22T22:31:17.619+02:00[Europe/Paris]]>
2016-09-22 22:31:17,621 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Building an authentication result for authentication org.apereo.cas.authentication.DefaultAuthentication@d8109559 and service https://testcas.example.com/philippe/eclipse/testcas/www/cas5v3.php>
2016-09-22 22:31:17,625 DEBUG [org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository] - <DefaultPrincipalAttributesRepository will return the collection of attributes directly associated with the principal object which are [{affiliation=groupMembership, cn=commonName, displayName=displayName, uid=uid, username=testuser}]>
2016-09-22 22:31:17,626 DEBUG [org.apereo.cas.authentication.principal.cache.AbstractPrincipalAttributesRepository] - <Found [5] cached attributes for principal [testuser] that are {affiliation=groupMembership, cn=commonName, displayName=displayName, uid=uid, username=testuser}>
2016-09-22 22:31:17,629 INFO [org.apereo.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: testuser
WHAT: TGT-**********************************************ndlBMK02zm-devcas1
ACTION: TICKET_GRANTING_TICKET_CREATED
APPLICATION: CAS
WHEN: Thu Sep 22 22:31:17 CEST 2016
CLIENT IP ADDRESS: 172.18.3.6
SERVER IP ADDRESS: testcas.example.com
=============================================================
>
2016-09-22 22:31:17,633 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.SpnegoCredentialsAction@1f9e7fa; result = success>
2016-09-22 22:31:17,633 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,634 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@80e64 expression = spnego, resultExpression = [null]]; result = success>
2016-09-22 22:31:17,634 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@a45f25 on = success, to = sendTicketGrantingTicket]>
2016-09-22 22:31:17,635 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'spnego'>
2016-09-22 22:31:17,635 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'sendTicketGrantingTicket' of flow 'login'>
2016-09-22 22:31:17,635 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@22a3e2 expression = sendTicketGrantingTicketAction, resultExpression = [null]]>
2016-09-22 22:31:17,636 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,636 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.SendTicketGrantingTicketAction@60a33>
2016-09-22 22:31:17,638 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.SendTicketGrantingTicketAction@60a33; result = success>
2016-09-22 22:31:17,638 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,639 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@22a3e2 expression = sendTicketGrantingTicketAction, resultExpression = [null]]; result = success>
2016-09-22 22:31:17,639 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@1395ed9 on = *, to = serviceCheck]>
2016-09-22 22:31:17,645 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'sendTicketGrantingTicket'>
2016-09-22 22:31:17,645 DEBUG [org.springframework.webflow.engine.DecisionState] - <Entering state 'serviceCheck' of flow 'login'>
2016-09-22 22:31:17,646 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@1a17398 on = flowScope.service != null, to = generateServiceTicket]>
2016-09-22 22:31:17,646 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'serviceCheck'>
2016-09-22 22:31:17,646 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'generateServiceTicket' of flow 'login'>
2016-09-22 22:31:17,647 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@1be8d2d expression = generateServiceTicketAction, resultExpression = [null]]>
2016-09-22 22:31:17,647 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,647 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.GenerateServiceTicketAction@1c0770e>
2016-09-22 22:31:17,648 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collecting authentication history based on [1] authentication events>
2016-09-22 22:31:17,649 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Evaluating authentication principal [testuser] for inclusion in result>
2016-09-22 22:31:17,651 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected principal attributes [{uid=uid, cn=commonName, affiliation=groupMembership, displayName=displayName, username=testuser}] for inclusion in this result for principal [testuser]>
2016-09-22 22:31:17,652 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [authenticationMethod] -> [JcifsSpnegoAuthenticationHandler]>
2016-09-22 22:31:17,654 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [successfulAuthenticationHandlers] -> [[JcifsSpnegoAuthenticationHandler]]>
2016-09-22 22:31:17,655 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Finalized authentication attributes [{authenticationMethod=JcifsSpnegoAuthenticationHandler, successfulAuthenticationHandlers=[JcifsSpnegoAuthenticationHandler]}] for inclusion in this authentication result>
2016-09-22 22:31:17,656 DEBUG [org.apereo.cas.authentication.DefaultPrincipalElectionStrategy] - <Nominated [testuser] as the primary principal>
2016-09-22 22:31:17,658 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Determined primary authentication principal to be [testuser]>
2016-09-22 22:31:17,659 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected authentication attributes for this result are [{authenticationMethod=JcifsSpnegoAuthenticationHandler, successfulAuthenticationHandlers=[JcifsSpnegoAuthenticationHandler]}]>
2016-09-22 22:31:17,661 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Authentication result commenced at [2016-09-22T22:31:17.661+02:00[Europe/Paris]]>
2016-09-22 22:31:17,662 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Building an authentication result for authentication org.apereo.cas.authentication.DefaultAuthentication@ead71d9 and service https://testcas.example.com/philippe/eclipse/testcas/www/cas5v3.php>
2016-09-22 22:31:17,664 DEBUG [org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository] - <DefaultPrincipalAttributesRepository will return the collection of attributes directly associated with the principal object which are [{affiliation=groupMembership, cn=commonName, displayName=displayName, uid=uid, username=testuser}]>
2016-09-22 22:31:17,666 DEBUG [org.apereo.cas.authentication.principal.cache.AbstractPrincipalAttributesRepository] - <Found [5] cached attributes for principal [testuser] that are {affiliation=groupMembership, cn=commonName, displayName=displayName, uid=uid, username=testuser}>
2016-09-22 22:31:17,669 INFO [org.apereo.cas.CentralAuthenticationServiceImpl] - <Granted ticket [ST-4-NhAexJRg9TwPZ5ZWJH3M-devcas1] for service [https://testcas.example.com/philippe/eclipse/testcas/www/cas5v3.php] and principal [testuser]>
2016-09-22 22:31:17,671 INFO [org.apereo.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: testuser
WHAT: ST-4-NhAexJRg9TwPZ5ZWJH3M-devcas1 for https://testcas.example.com/philippe/eclipse/testcas/www/cas5v3.php
ACTION: SERVICE_TICKET_CREATED
APPLICATION: CAS
WHEN: Thu Sep 22 22:31:17 CEST 2016
CLIENT IP ADDRESS: 172.18.3.6
SERVER IP ADDRESS: testcas.example.com
=============================================================
>
2016-09-22 22:31:17,672 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.GenerateServiceTicketAction@1c0770e; result = success>
2016-09-22 22:31:17,673 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,673 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@1be8d2d expression = generateServiceTicketAction, resultExpression = [null]]; result = success>
2016-09-22 22:31:17,673 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@1d98f9e on = success, to = warn]>
2016-09-22 22:31:17,674 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'generateServiceTicket'>
2016-09-22 22:31:17,674 DEBUG [org.springframework.webflow.engine.DecisionState] - <Entering state 'warn' of flow 'login'>
2016-09-22 22:31:17,674 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@e74283 on = *, to = redirect]>
2016-09-22 22:31:17,675 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'warn'>
2016-09-22 22:31:17,675 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'redirect' of flow 'login'>
2016-09-22 22:31:17,676 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@1338437 expression = flowScope.service.getResponse(requestScope.serviceTicketId), resultExpression = requestScope.response]>
2016-09-22 22:31:17,676 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,677 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,677 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@1338437 expression = flowScope.service.getResponse(requestScope.serviceTicketId), resultExpression = requestScope.response]; result = success>
2016-09-22 22:31:17,678 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@195d5da on = *, to = postRedirectDecision]>
2016-09-22 22:31:17,678 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'redirect'>
2016-09-22 22:31:17,678 DEBUG [org.springframework.webflow.engine.DecisionState] - <Entering state 'postRedirectDecision' of flow 'login'>
2016-09-22 22:31:17,679 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@c1208a on = *, to = redirectView]>
2016-09-22 22:31:17,679 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'postRedirectDecision'>
2016-09-22 22:31:17,679 DEBUG [org.springframework.webflow.engine.EndState] - <Entering state 'redirectView' of flow 'login'>
2016-09-22 22:31:17,680 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.springframework.webflow.action.ViewFactoryActionAdapter@1cc485>
2016-09-22 22:31:17,680 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.springframework.webflow.action.ExternalRedirectAction@f6e885>
2016-09-22 22:31:17,681 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.springframework.webflow.action.ExternalRedirectAction@f6e885; result = success>
2016-09-22 22:31:17,681 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.springframework.webflow.action.ViewFactoryActionAdapter@1cc485; result = success>
2016-09-22 22:31:17,681 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,681 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,682 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,682 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,682 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,682 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,683 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,683 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,683 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,683 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,684 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,684 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,684 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,684 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,828 DEBUG [org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository] - <DefaultPrincipalAttributesRepository will return the collection of attributes directly associated with the principal object which are [{affiliation=groupMembership, cn=commonName, displayName=displayName, uid=uid, username=testuser}]>
2016-09-22 22:31:17,829 DEBUG [org.apereo.cas.authentication.principal.cache.AbstractPrincipalAttributesRepository] - <Found [5] cached attributes for principal [testuser] that are {affiliation=groupMembership, cn=commonName, displayName=displayName, uid=uid, username=testuser}>
2016-09-22 22:31:17,831 INFO [org.apereo.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: testuser
WHAT: ST-4-NhAexJRg9TwPZ5ZWJH3M-devcas1
ACTION: SERVICE_TICKET_VALIDATED
APPLICATION: CAS
WHEN: Thu Sep 22 22:31:17 CEST 2016
CLIENT IP ADDRESS: 172.16.10.177
SERVER IP ADDRESS: testcas.example.com
=============================================================
>
2016-09-22 22:31:17,833 DEBUG [org.apereo.cas.authentication.AuthenticationContextValidator] - <Attempting to match requested authentication context mfa-yubikey against []>
2016-09-22 22:31:17,834 DEBUG [org.apereo.cas.authentication.AuthenticationContextValidator] - <No authentication context could be determined based on authentication attribute authnContextClass>
2016-09-22 22:31:17,834 DEBUG [org.apereo.cas.authentication.AuthenticationContextValidator] - <No satisfied multifactor authentication providers are recorded in the current authentication context.>
Second pass :
2016-09-22 22:31:25,701 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <0 expired tickets removed.>
2016-09-22 22:31:25,702 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Finished ticket cleanup.>
2016-09-22 22:32:25,703 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <0 expired tickets removed.>
2016-09-22 22:32:25,704 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Finished ticket cleanup.>
2016-09-22 22:33:01,470 DEBUG [org.springframework.webflow.executor.FlowExecutorImpl] - <Launching new execution of flow 'login' with input map['service' -> 'https://testcas.example.com/philippe/eclipse/testcas/www/cas5v3.php']>
2016-09-22 22:33:01,470 DEBUG [org.springframework.webflow.definition.registry.FlowDefinitionRegistryImpl] - <Getting FlowDefinition with id 'login'>
2016-09-22 22:33:01,471 DEBUG [org.springframework.webflow.engine.Flow] - <Creating [FlowVariable@17f0abb name = 'credential', valueFactory = [BeanFactoryVariableValueFactory@7ad7ff type = UsernamePasswordCredential]]>
2016-09-22 22:33:01,479 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@12fb90f expression = initialFlowSetupAction, resultExpression = [null]]>
2016-09-22 22:33:01,479 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:33:01,480 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.InitialFlowSetupAction@2c1fd6>
2016-09-22 22:33:01,482 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.InitialFlowSetupAction@2c1fd6; result = success>
2016-09-22 22:33:01,484 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:33:01,485 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@12fb90f expression = initialFlowSetupAction, resultExpression = [null]]; result = success>
2016-09-22 22:33:01,485 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'initialAuthenticationRequestValidationCheck' of flow 'login'>
2016-09-22 22:33:01,485 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@1c95611 expression = initialAuthenticationRequestValidationAction, resultExpression = [null]]>
2016-09-22 22:33:01,485 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:33:01,486 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.InitialAuthenticationRequestValidationAction@18b8f92>
2016-09-22 22:33:01,500 DEBUG [org.apereo.cas.authentication.AuthenticationContextValidator] - <Attempting to match requested authentication context mfa-yubikey against []>
2016-09-22 22:33:01,501 DEBUG [org.apereo.cas.authentication.AuthenticationContextValidator] - <No authentication context could be determined based on authentication attribute authnContextClass>
2016-09-22 22:33:01,502 DEBUG [org.apereo.cas.authentication.AuthenticationContextValidator] - <No satisfied multifactor authentication providers are recorded in the current authentication context.>
2016-09-22 22:33:01,503 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.InitialAuthenticationRequestValidationAction@18b8f92; result = mfa-yubikey>
2016-09-22 22:33:01,503 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:33:01,503 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@1c95611 expression = initialAuthenticationRequestValidationAction, resultExpression = [null]]; result = mfa-yubikey>
2016-09-22 22:33:01,503 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@16205d0 on = mfa-yubikey, to = mfa-yubikey]>
2016-09-22 22:33:01,503 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'initialAuthenticationRequestValidationCheck'>
2016-09-22 22:33:01,503 DEBUG [org.springframework.webflow.engine.SubflowState] - <Entering state 'mfa-yubikey' of flow 'login'>
2016-09-22 22:33:01,503 DEBUG [org.springframework.webflow.definition.registry.FlowDefinitionRegistryImpl] - <Getting FlowDefinition with id 'mfa-yubikey'>
2016-09-22 22:33:01,503 DEBUG [org.springframework.webflow.engine.SubflowState] - <Calling subflow 'mfa-yubikey' with input map[[empty]]>
2016-09-22 22:33:01,503 DEBUG [org.springframework.webflow.engine.Flow] - <Creating [FlowVariable@db6ca7 name = 'credential', valueFactory = [BeanFactoryVariableValueFactory@1a0b4be type = YubiKeyCredential]]>
2016-09-22 22:33:01,504 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@1e5e15f expression = initialFlowSetupAction, resultExpression = [null]]>
2016-09-22 22:33:01,504 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:33:01,504 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.InitialFlowSetupAction@2c1fd6>
2016-09-22 22:33:01,505 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.InitialFlowSetupAction@2c1fd6; result = success>
2016-09-22 22:33:01,505 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@1e5e15f expression = initialFlowSetupAction, resultExpression = [null]]; result = success>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'initializeLoginForm' of flow 'mfa-yubikey'>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@200c10 expression = initializeLoginAction, resultExpression = [null]]>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.InitializeLoginAction@10826f8>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.InitializeLoginAction@10826f8; result = success>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@200c10 expression = initializeLoginAction, resultExpression = [null]]; result = success>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@39452e on = success, to = viewLoginFormYubiKey]>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'initializeLoginForm'>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.engine.ViewState] - <Entering state 'viewLoginFormYubiKey' of flow 'mfa-yubikey'>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [SetAction@1648d0c name = viewScope.principal, value = conversationScope.authentication.principal]>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [SetAction@1648d0c name = viewScope.principal, value = conversationScope.authentication.principal]; result = success>
2016-09-22 22:33:01,527 DEBUG [org.springframework.webflow.engine.ViewState] - <Rendering + [ServletMvcView@121f1f view = org.thymeleaf.spring4.view.ThymeleafView@1f3de5c]>
2016-09-22 22:33:01,527 DEBUG [org.springframework.webflow.engine.ViewState] - < Flash scope = map[[empty]]>
2016-09-22 22:33:01,527 DEBUG [org.springframework.webflow.engine.ViewState] - < Messages = [DefaultMessageContext@f70275 sourceMessages = map[[null] -> list[[empty]]]]>
2016-09-22 22:33:01,623 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the new state is 'viewLoginFormYubiKey' in flow 'mfa-yubikey'>
2016-09-22 22:33:01,626 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the new state is 'viewLoginFormYubiKey' in flow 'mfa-yubikey'>
2016-09-22 22:33:25,706 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <0 expired tickets removed.>
Any idea ?
Regards.
First test :
- Login form
- yubikey
=> it works as expected (login+password, then yubikey token, then logged to application)
Second test :
- SPNEGO
- yubikey
=> works oddly : my client service page uses phpCAS, on first pass I get an "Authentication Error, try again", If I click on "try again", then yubikey token is asked, and after validation, I'm logged to the application.
I suspect that transition on success after SPNEGO to be incorrect. It's hardcoded to CasWebflowConstants.TRANSITION_ID_SEND_TICKET_GRANTING_TICKET, but MFA shoud be inspected before sending TGC, shouldn't it ?
Here's the log, first pass :
2016-09-22 22:29:25,698 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <0 expired tickets removed.>
2016-09-22 22:29:25,698 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Finished ticket cleanup.>
2016-09-22 22:30:09,078 DEBUG [org.springframework.webflow.executor.FlowExecutorImpl] - <Resuming flow execution with key '6010b9af-cc40-4b75-8f87-da32571c10b9_ZXlKaGJHY2lPaUpJVXpVeE1pSjkuZFV4cFZTdFNRbFoxTDBneVdGbEZSMnBGVTBGSlVWbFhlbE5KVVdKMk1VbGxhRFZ3T1V0dVJuVnJWalZTZEhoek5EaDJOVEpVTlVORFZYQnhSaTlPUzBvM05FSXJOMkpMZWxWVFpVNHJkR3N4SzFCRFFuZzVkM1JuTkRsRGQwcE5aSGgwZEhWbVFrWjJOV3BvYlRka2QxcGhSbGxHTHk5cWRFWTVObTVNVm5reU9UVmFTMVZvU1hGUWIzTmpla1Y0VGpCeFN5OTRjRzlyV1VwT1ZYVjBUV3RSZDBwVVdtMDRlbHBwTVdOMWJIaGtjRUpQTDNaSlYxWldSVXBpUVZsRU5pdENlVEZTWW14TGVHVk5ha1JvT1daSGJWcG1TV04xZHpSdlkxVlNWalpJWjNCS01uaHBNM1ZxWTA1UFltZFZRMEp6V0cxeE16QmpSRVJDYVVkSlJVTlBXbmxZTjNsclVqTXhhMjlPUmtwUE1UTjVUR3BGY1RrdmExaFNWVWh1TDNGU1JrcFdlbkZ2WWxGWVdHRnBZMjk1T1VoRkt6SXdSbTEwZG5oclJucDJNekkwTm1aTk5rTldlRk5JYWl0SllrTlRhMlF2WVhWc2NrOVRSQ3RxVFZFNFJYWk5XRkJaZUZocFJEaDJlRFEwWTBkc01GSkhiakpYZVhKdU9IcG9ORzVzTWk5RU5tNVlSVkIzVEhSVGMwWktURmd3VG1GRldVZFBjMFZxUVZVM01IbzJUVTlCVUZSWldsUkVaVTk0WlVsVmJGaENMekJpYmpGcE5FcEZPVW81TDBkeE9YZzJWUzlFTXk5T1ZWWkpXblZsTUhSQ2RERkZXWFZEVkRSVlVWZEZSVEEzYVdvMWJVTkVVbWx3TlZsRE5uQmFPVTVFV1RkRVpYTklTV3BRYW5kUlRXRmpRWEZNVGs1YWNVNTNZbnA1TUZSSldFcFlhSGRHTW1WWE5TdDBlV0pNUjNKNE5FdHFPWGRTTjNveGFrcHBOR2t2VkhJclUzUndaamh3TTAxeUx6VktSRkpOY1Rodk0zRkRWSGgzT1ZkNU9XeEVWR1l5Y0dKaFN6bGhNM2t6Vm1ka01GWktVak5GT1VkaFFsQkVkRzFsZVZKc1pHUjFSR2cwUzNSdU1rSlFkV2RaYjBOQ1Z6TlBabTh5U1dkUVNteFJRbFJoYm5WV0swOTJOR1ZIYlhsSGExWndXR2hPY1RoQmNuRmxPVFZ1YmxaWGRWSmxkalpQVHpjMlRFaEJjbTk2Ykc1ME5FVnphRmhRYzJoTFNFRjFTbmhaV1dOall6SnFjbnBJYTFwTVlUaEpOSFF2T1ZaemNVMHZaM2xITmpOSVEyTkZUMFZDY25KaFpuSm9SbTB6WVZOUWJsSnBNaXRIY1VWbFNqRnBjbVoyWkdRd2NHUnljWGd5UjFoSmJYZDZTWFJ5YzNOMWRuUkhXVFJWVGl0MlRHcGhXVUkwUTBONVVsTk9hMUZJTnpNMGQxWlFkak54VG05WGIyRlFhRkZMVlRGRVVWWm5aVUkxTldGamNESnZNRFJxTDJOb2FWVmlaazlJY2tWa2RtcEhjRlJ3ZGtzd2RIcHFiRGxVZVZGc01tbERUQzl6WjNSRWNtSnlhSFE1U2pSelVVVkVTMUpJTmtGcVdXMUpTa2c0Ym1aNlFYZFVia3N3WmpoMVozTnVZVXBVUWpkb09TdEdOVk5CTTI5WmQxSnBaVXh6UjJ0WmNFcDNNV04zUW01elRWTTFVMDlQVjNrellubEdZMWhZWjNvdmNHMUVRME4zYm1NelJFNXVlR3hwZVhvMlMzb3ZNMUpYZFdkMVIxZzJWVzFrTWpadVFreHBLM0puZG5WYWNWSjFibWRoZGxBdlprSnlSMDAyY0RCcFJISjZaR0ZETm01dVZYWnNTV3h0TmtaU05rSkZhVWM0V0dGbGJGaHlTMll3TW1aS1ZreHZVazFwZWxKMVdsaG9ORWh1YjFNcmMzaFFPVzVyTmk5aUszSmhkMVJqV21aa2MwNURTa1ZwVGxkTFFuZEZlRlZ5YUVGUFUyNURVSFJMVUd4eFYxa3JNVVZtZVhwdU1IRTNRMWN4ZVVWbGVtaDNiRzR3WTJKcFpFMXpNQ3RWV0VOTFdYcFdibGt3UjJaRlNqTnBNakpoUTFkU05rZ3ZhbUZHVDNaSWNXUm1jRFV5YUVWclZVbENWbVF3VVU1R04zbHNXU3RDYkhGVlJWbG1WbmRwU1dSWWRuTm5aMVptY25oUldTc3pVVlJXTVhwUFZ6a3pkVVV6YzJsRlZWbDBUUzh5ZWxOblJXWTRXbTFLUkVSV1dIWkZjWEp5WnpkdVZrbFdSREJIYUVaQlJYZ3pMMlZvYzNCMmNURk9SeTk1WTJWeFl6aHRlbFZaVlhCdGJ6VkpVVFFyVWt4cFlVZEJNemQwUkdSQ2VXdzVhV1puYld0NU5tVjFjbGRpVEdOVlIyMDBTR0ZrU0hJNWJHSkdjMHQxVFRZMGRVcFNPVmRHUWpsNlJXdHdla040Tkc5eGRFcFlWMVZKU1hkWmFWVnJVRlJ2U0dWVFQzUTRaVWRsYkZkTFNWaFljRWRCWmxsQmF5dE1Oa3BYZVhkeE1UQjVZMGhFVmtnNVQwNWhTMWRQZVdRMUwxcGlkUzlGWlc0NFFUSk5PR1phT0doTFR6SldaMUppYW05eFJraFNTRk00WTFobWQyZ3plV0p6YmxObk5HUmxhRTQxWkhNemNVbFNaa3d4UWpoc2NITXdVMkZIUXk5MlQyOWlTMGhTY1hKaU1VdFFSa05OUzNsWFlqTk1aV2hVUW5rMk4zWm9MelIwTjBSaU5YRkhTbGhsWTJRNFN6UnlXbVZ3YlhVMFVqbFVZbU40WTFwNVMyTnVlRGN3YWxWMldteFpUMmN6VmtGM01uTmlUMk16TjNJd2JXcDJMMUZDUjJ4YVRsVXJSV3BWU1ZaQk1FMDJiekpyWnpCVFkxazVTMUpHZUZabE1YQXpUbE5sY2pCYVQzSldTRmxxZDFRNFkxcEtjVmxXYUdaMlNFZHhTVEJhVTFOWllYZHVXbGhQZHpkUll6aHdObXBFY2pjcmVqVmhWbGN6TVdKb00wZ3dlbXBQU205UWNtUlNZM0pxY1V4NGRHMDVLMUZ4ZVM5blVuaE9ZMEprTTBOUVYyVTBkVFJRZFdSVE1FUlJUVFJrTUhwYVZVcFZiRUV2VG5GM1Z6SklWblZyVkRaV2FsbHNSazV6TjB4Q1FXMTJZVTF1YVRWRVRsRjBkV052UWs5c2FHdFpOMlZzT1ZwbU1VcFRlSEpRWmtsNlRWQllUekkxVkROMk4wMVVLM1ZEUm1SdGFXbzRMMm96Tnk5NU1tYzBjemd5YUZGdFJqRXZURWxTVDJOaVNERTBkR2RTYlVocU1GVkZZekZDT1ZWWWFGbFhXWEFyVEVWUllrTllRMU5uTW5WeWNFUmFOblZvWmxoV1ZYRkJVWEpGZGxVelluVkhOQzgzVURsa2NGbHVRWGhhTHpReFNsRkNNMGR3TjNwcmQzazBjREZFZG1Sb2RHSkViMFZqUzFOeFVqVjVXVGxMS3pOTVUyWXdja1pUT0RkTE1TOXpOeXRhYm5kaFZHSjNhVWRSWW14NlEwWk9TbFZyUkdOak4xTTRZeTlwVm04ekwyRlZZMFJXTVRNclRGZGpSVUp6WkN0c1QwUlpOSEpHUkVRMGFFdzVaVmxzVlhkTU5WbHFWa000THpkcWVVaHlXVUpGUkZFMFIxVjRWbkY1TmpKMk1sVllNekV2UkhKTE1tMUVhQ3RwVURocFpYVnFVekpRY0haSU1HRTVkemhHYTIxNldXRjVXbFZrVkZCMGVUVktRbTVOUkcxSmFVRk5ja0kwYzJaUlpqTnBZbUZqV2xGTFVIZFRSQzk2Vlc5TFUwSnJOVXRZUmtKSE1tSk5aMjVDVDFGcGR6QTFjakpSZHpjM1UyODVRV3hHVVdwb1VHSm1iMlY0U2tOb1JFSjJkamx0T1ZOcFZDdEdkbTl6T0hKVVQyc3lNRnBaUWpWWFZGSkViemxVUVVkWWVXRklNekpRUVZoYVVTdDRSbXRFVUVwT1QwSllZekJFV1RsTlNIRjVNSFYxVFVSdlJqaGFhVEZLTWxrdmVFcExXVWxDU1UxNlprOVVWbGhNTlZRMVpGVTBhbmhOVnk5blZUWTFSbU16VTJRNUwyZHVNMmN6Wm14VVExWXJlbE52YjNWaVVXdG1lR0poYXpWVFluWkpkbFF3VEZaR01rZElZMWx1Y1ZwVVFuUlVSWEpyUWtoUmFVczVMeXRNVGtad09GRkZNa1JXWVcxcGJHOTVhVzlLYkVWNlREQjZLMHByY2tsSmNrSTViMkpUZHk5V1dHRkRTWFZEVTA1NFNERkVTV2hLUVhsNFZFVTRXR1J1UWt0NGNrWlZXbEJIUldObFFrUTFWSFV4VDNsdVdIbFdMMlpIYkdSSFRuSkhRa013UlZsMmEyMVlaMGxIZFdNMlpqTk5TVmxDVFRSU2VqSjRZbEprTTIwdlZ6RXZOR1pZTHpRemJHeFliSFJGY0hvNE5URmlkRzFJYWxZeVVFdEpkMFpHU1U1c2RuZzFhVmh1U1hVeE5rbHJOelZ1ZGpBMlpGVnlWbGRwWkhWRlVVa3lVRVpvWWk5VlVsTkxVMEZ4VW1oTmJrOVZVbVpxTUhOS1pGRmlNVXBMWTJKUkwybFZPVE5oYXl0dVdFSk5XVzFETjI5UGJFeHpWbEozTlRCYWIwWk5WelF5YTA5VWVsbHJlWFpPTVRCVVpVaGhNVXBqTTFoSk1tNXVSRWhXTVRSb1dqRkhORW94ZDBKNGFtdHhPR2hVUTNsNVMxVTBUREJSWmpZeVJEWjBUMk1yTVdGdmRVbG9RaTlpWkZOUmFtSlRLM3BXZFRBemJ6aFNXblJYVWtOWlFrcGtTMnBSZEZaVE0yYzNNMWh1YUhkaVIybHRZbGh6T0c0MldGVmxUalZLUzNsaFlXVlZOVVZpTkVKclQwazBRV05MVVd0UFdVTjBiRkZKV0d0dlNVcGtOMEpEU2pkeVRIQXdSMVIwU0ZkdE1YWkVTblZMY0ZOU2F6TnhlR3htU1VsMlFWaExhME15U1hkSk5IaHZaM0JIZUdoTmFXWlBNSEJsTlhsdU5FUnpLekV2V21ocmFtWjBSRmxXTDFocVRHTTFObmhYU2xJMFpWcGFaWEl6Vm5oVWRHeFRZME41Y1dkNlZVa3JLMVE0TkhwdE9EZEJkRWhQZG1RcmNqQlViVXR1UkVWb2QzbzBZV00yZURJeVJ6VnVlRW96TldoTlZteGphV1pMYUdJMWVUaDBOVTlzVmk5QlpqUTNkakpCWVZnck5GVnljWGx5U1ZRMllqaE9ZMElyWTI1QmVFa3hZMWxQYjBKS1YyeFhaVGx5VlRsUlNFcFplSHBZVUc1WmRrTTFWVTVEU0VZMVkwRXZSamRRZFV4VGVYRkVTR3BSTVhkb2FYRjJXV1pzZFcwelJDOWtZWEpJZHpaUVZuUnhTVUV5YmxKaVUzSXZRbEJvYVdGUlZYRmxVMjVSUjFReFFTOXVaVU5EVTBJNWFuTldUbGhrYzIxV2EzQlZWV2xtZDBSQk9FWmlOMlZOTVU1UmRYRkpXalYyY0dOV1IwWk5WSGhEYW1WR1VsSmxNMHQxVWl0RWJuQkZNMkZuWnpWeFVUQXpRM1pGUzNoU1ZIVlFkVzlDTkRGM2JqZ3djR3A2Y0hGQmNqZHBaaTlxT1VwTllYaFBXVEJEV2toT1JIcEtlREZhYjFrNFlVUk5RMEZRUjB4SGJrSnRTWG81Umpkc0x6WjBOSE51T0VNeWIxaG5SakF3YUdsVVRHVk5jSGxKVUVoTVdqRkpTRkpJYjFabWVFZFVXQzlUVnpSd1dEQlFZa0pqV2xGaFJYTlZWRVF6UkVvdmMxUkVOSFJFUkU5d2Vrd3ZaR1ZDY1VnM01uQlJWV1ZPVjA1U1lYSlJabFZOUTFWaFNtNHZlRkp2ZWpGdVoyMDNOMWxIV25SU1kzbElaMFZQU2poWVZVaGFiVGRGZFZWcGVETldlbmRXYVcwNWMzZGhZa2R5TWtwalFrWmtiM2hhWjBOMFMxTnhlWHBCVDJ4MVdqVktkVzFDTlVSVVQxbExRWGR1UTBGS09WcElTamgwYVVFMVpreDVTa2hTYWtKdGRGWlpNMVZUYkVGQ1NXTjZaVXRXUzBaNk5uaFRSa0pUTVVSVFZWRkVTMVphWkdaWVlYUnRWREZ3U2s5TWVXeFJiWFp6Tmxoc2VXbGxXbU5oZDIxUEwxUkhkbUZqV21zdk0xTTFOM0IxYzFSM1VDdDVRVTR4VEZCSFNraGFTRXAwYkhkMVZIZG5aVk1yWlcxdVNtc3hlbTVwVTJaM1lWRk1XbnBwTkd4SmJGWmlUMk4wVERCcVEwRTFkRlkwTjJFMlVTdGpPVWhEU1NzMGVtMVlNMWRPUjFKQ1VYaEtSRWN2T1ZKdGNITldkVzQzTlc4dlpIbE9iVlZ2VDJGMVJHaHFkbXd4Tm5GUlVXMTRWa2hqVlZObFN6WXdUek5xUzNSaWJFNUlXV0ZPYXk5NmFuWnNRekJ6Tnpkck5GUjFTV3R3YUZsMmRFRXhjM1V3Y2pVNWQyaGhiVzlsYWs5R1prRXlkMnRoVFZsTU5rMVJjbkpRY1c5SGMyeEhhbTFhZWtnclFXUnRTblJHUTJkMVZtNW9jRGhwWWtsbVNubFNZVzR3Y2xsS1QzRTFNRVI0WkZkaWNXNXBZamc1ZWpKVVR6TnRUbUY0YUVsdVIwTjZZVE14WTFJeWExSlhMM0p4VlZscE0xaFhMMnN6TlhKYU9IZFZXREpzU2pSNGJXVnRiVlZTWldWSGExWTJhWFEyVUVOM2NFWmplSFlyY0VWaVltWnRNMUpCYWxjdlltNXRNM2t2WWpSM1pqSm9RbkZFZVVkUmFpOWlMMFpVZVZGSldXdERTVGQ1V21sUlVtczkub08ybHRYRDd5MjhqdnlWYUZvb2wyYWhEV2xDcnE5Ql95X3d1c2tJMnNGWDBjM2k0WUlJZ3VGempRX2ZBTW9ValVuejVzR0g0eXROaDJlTURDcVdzc2c=>
2016-09-22 22:30:09,085 DEBUG [org.springframework.webflow.definition.registry.FlowDefinitionRegistryImpl] - <Getting FlowDefinition with id 'login'>
2016-09-22 22:30:09,085 DEBUG [org.springframework.webflow.definition.registry.FlowDefinitionRegistryImpl] - <Getting FlowDefinition with id 'mfa-yubikey'>
2016-09-22 22:30:09,085 DEBUG [org.springframework.webflow.engine.Flow] - <Restoring [FlowVariable@db6ca7 name = 'credential', valueFactory = [BeanFactoryVariableValueFactory@1a0b4be type = YubiKeyCredential]]>
2016-09-22 22:30:09,115 DEBUG [org.springframework.webflow.engine.ViewState] - <Rendering + [ServletMvcView@e83f9c view = org.thymeleaf.spring4.view.ThymeleafView@403fe0]>
2016-09-22 22:30:09,115 DEBUG [org.springframework.webflow.engine.ViewState] - < Flash scope = map[[empty]]>
2016-09-22 22:30:09,115 DEBUG [org.springframework.webflow.engine.ViewState] - < Messages = [DefaultMessageContext@11e713c sourceMessages = map[[null] -> list[[empty]], 'token' -> list[[Message@2a0a13 source = 'token', severity = ERROR, text = 'required on token']]]]>
2016-09-22 22:30:25,700 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <0 expired tickets removed.>
2016-09-22 22:30:25,700 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Finished ticket cleanup.>
2016-09-22 22:31:17,096 DEBUG [org.springframework.webflow.executor.FlowExecutorImpl] - <Launching new execution of flow 'login' with input map['service' -> 'https://testcas.example.com/philippe/eclipse/testcas/www/cas5v3.php']>
2016-09-22 22:31:17,097 DEBUG [org.springframework.webflow.definition.registry.FlowDefinitionRegistryImpl] - <Getting FlowDefinition with id 'login'>
2016-09-22 22:31:17,097 DEBUG [org.springframework.webflow.engine.Flow] - <Creating [FlowVariable@17f0abb name = 'credential', valueFactory = [BeanFactoryVariableValueFactory@7ad7ff type = UsernamePasswordCredential]]>
2016-09-22 22:31:17,099 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@12fb90f expression = initialFlowSetupAction, resultExpression = [null]]>
2016-09-22 22:31:17,100 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,100 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.InitialFlowSetupAction@2c1fd6>
2016-09-22 22:31:17,101 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.InitialFlowSetupAction@2c1fd6; result = success>
2016-09-22 22:31:17,102 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,103 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@12fb90f expression = initialFlowSetupAction, resultExpression = [null]]; result = success>
2016-09-22 22:31:17,103 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'initialAuthenticationRequestValidationCheck' of flow 'login'>
2016-09-22 22:31:17,103 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@1c95611 expression = initialAuthenticationRequestValidationAction, resultExpression = [null]]>
2016-09-22 22:31:17,104 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,104 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.InitialAuthenticationRequestValidationAction@18b8f92>
2016-09-22 22:31:17,104 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.InitialAuthenticationRequestValidationAction@18b8f92; result = success>
2016-09-22 22:31:17,105 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,105 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@1c95611 expression = initialAuthenticationRequestValidationAction, resultExpression = [null]]; result = success>
2016-09-22 22:31:17,105 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@14a857c on = success, to = ticketGrantingTicketCheck]>
2016-09-22 22:31:17,105 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'initialAuthenticationRequestValidationCheck'>
2016-09-22 22:31:17,106 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'ticketGrantingTicketCheck' of flow 'login'>
2016-09-22 22:31:17,106 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@12e9394 expression = ticketGrantingTicketCheckAction, resultExpression = [null]]>
2016-09-22 22:31:17,106 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,106 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.TicketGrantingTicketCheckAction@21f96a>
2016-09-22 22:31:17,107 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.TicketGrantingTicketCheckAction@21f96a; result = notExists>
2016-09-22 22:31:17,107 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,107 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@12e9394 expression = ticketGrantingTicketCheckAction, resultExpression = [null]]; result = notExists>
2016-09-22 22:31:17,107 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@135045f on = notExists, to = gatewayRequestCheck]>
2016-09-22 22:31:17,108 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'ticketGrantingTicketCheck'>
2016-09-22 22:31:17,108 DEBUG [org.springframework.webflow.engine.DecisionState] - <Entering state 'gatewayRequestCheck' of flow 'login'>
2016-09-22 22:31:17,108 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@138f996 on = *, to = serviceAuthorizationCheck]>
2016-09-22 22:31:17,109 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'gatewayRequestCheck'>
2016-09-22 22:31:17,109 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'serviceAuthorizationCheck' of flow 'login'>
2016-09-22 22:31:17,109 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@16557fe expression = serviceAuthorizationCheck, resultExpression = [null]]>
2016-09-22 22:31:17,109 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.ServiceAuthorizationCheck@41dba0>
2016-09-22 22:31:17,111 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.ServiceAuthorizationCheck@41dba0; result = success>
2016-09-22 22:31:17,112 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@16557fe expression = serviceAuthorizationCheck, resultExpression = [null]]; result = success>
2016-09-22 22:31:17,112 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@1950931 on = *, to = initializeLoginForm]>
2016-09-22 22:31:17,112 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'serviceAuthorizationCheck'>
2016-09-22 22:31:17,113 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'initializeLoginForm' of flow 'login'>
2016-09-22 22:31:17,113 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@1ce528f expression = initializeLoginAction, resultExpression = [null]]>
2016-09-22 22:31:17,113 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,113 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.InitializeLoginAction@10826f8>
2016-09-22 22:31:17,113 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.InitializeLoginAction@10826f8; result = success>
2016-09-22 22:31:17,114 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,114 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@1ce528f expression = initializeLoginAction, resultExpression = [null]]; result = success>
2016-09-22 22:31:17,114 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@1b6e8e9 on = success, to = clientIp]>
2016-09-22 22:31:17,114 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'initializeLoginForm'>
2016-09-22 22:31:17,115 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'clientIp' of flow 'login'>
2016-09-22 22:31:17,115 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@5f8386 expression = ipBasedDispatcher, resultExpression = [null]]>
2016-09-22 22:31:17,115 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,115 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing fr.chpoitiers.cas.web.flow.NetworkBasedClientAction@d92576>
2016-09-22 22:31:17,116 DEBUG [fr.chpoitiers.cas.web.flow.NetworkBasedClientAction] - <Read Ip from request : 172.18.3.6 returning : interne>
2016-09-22 22:31:17,116 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing fr.chpoitiers.cas.web.flow.NetworkBasedClientAction@d92576; result = interne>
2016-09-22 22:31:17,117 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,117 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@5f8386 expression = ipBasedDispatcher, resultExpression = [null]]; result = interne>
2016-09-22 22:31:17,117 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@160ce7d on = interne, to = startSpnegoAuthenticate]>
2016-09-22 22:31:17,117 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'clientIp'>
2016-09-22 22:31:17,118 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'startSpnegoAuthenticate' of flow 'login'>
2016-09-22 22:31:17,118 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@75b2f4 expression = negociateSpnego, resultExpression = [null]]>
2016-09-22 22:31:17,118 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,119 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.SpnegoNegociateCredentialsAction@1623aa0>
2016-09-22 22:31:17,119 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.SpnegoNegociateCredentialsAction@1623aa0; result = negotiate>
2016-09-22 22:31:17,119 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,119 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@75b2f4 expression = negociateSpnego, resultExpression = [null]]; result = negotiate>
2016-09-22 22:31:17,120 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@82e673 on = negotiate, to = casSpnegoNegotiateView]>
2016-09-22 22:31:17,120 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'startSpnegoAuthenticate'>
2016-09-22 22:31:17,120 DEBUG [org.springframework.webflow.engine.EndState] - <Entering state 'casSpnegoNegotiateView' of flow 'login'>
2016-09-22 22:31:17,120 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.springframework.webflow.action.ViewFactoryActionAdapter@bf1356>
2016-09-22 22:31:17,234 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.springframework.webflow.action.ViewFactoryActionAdapter@bf1356; result = success>
2016-09-22 22:31:17,234 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,234 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,234 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,234 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,234 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,234 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,234 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,431 DEBUG [org.springframework.webflow.executor.FlowExecutorImpl] - <Launching new execution of flow 'login' with input map['service' -> 'https://testcas.example.com/philippe/eclipse/testcas/www/cas5v3.php']>
2016-09-22 22:31:17,431 DEBUG [org.springframework.webflow.definition.registry.FlowDefinitionRegistryImpl] - <Getting FlowDefinition with id 'login'>
2016-09-22 22:31:17,431 DEBUG [org.springframework.webflow.engine.Flow] - <Creating [FlowVariable@17f0abb name = 'credential', valueFactory = [BeanFactoryVariableValueFactory@7ad7ff type = UsernamePasswordCredential]]>
2016-09-22 22:31:17,432 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@12fb90f expression = initialFlowSetupAction, resultExpression = [null]]>
2016-09-22 22:31:17,433 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,433 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.InitialFlowSetupAction@2c1fd6>
2016-09-22 22:31:17,433 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.InitialFlowSetupAction@2c1fd6; result = success>
2016-09-22 22:31:17,433 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,433 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@12fb90f expression = initialFlowSetupAction, resultExpression = [null]]; result = success>
2016-09-22 22:31:17,433 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'initialAuthenticationRequestValidationCheck' of flow 'login'>
2016-09-22 22:31:17,433 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@1c95611 expression = initialAuthenticationRequestValidationAction, resultExpression = [null]]>
2016-09-22 22:31:17,433 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,433 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.InitialAuthenticationRequestValidationAction@18b8f92>
2016-09-22 22:31:17,434 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.InitialAuthenticationRequestValidationAction@18b8f92; result = success>
2016-09-22 22:31:17,434 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,434 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@1c95611 expression = initialAuthenticationRequestValidationAction, resultExpression = [null]]; result = success>
2016-09-22 22:31:17,437 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@14a857c on = success, to = ticketGrantingTicketCheck]>
2016-09-22 22:31:17,437 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'initialAuthenticationRequestValidationCheck'>
2016-09-22 22:31:17,438 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'ticketGrantingTicketCheck' of flow 'login'>
2016-09-22 22:31:17,438 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@12e9394 expression = ticketGrantingTicketCheckAction, resultExpression = [null]]>
2016-09-22 22:31:17,438 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,438 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.TicketGrantingTicketCheckAction@21f96a>
2016-09-22 22:31:17,439 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.TicketGrantingTicketCheckAction@21f96a; result = notExists>
2016-09-22 22:31:17,439 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,439 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@12e9394 expression = ticketGrantingTicketCheckAction, resultExpression = [null]]; result = notExists>
2016-09-22 22:31:17,440 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@135045f on = notExists, to = gatewayRequestCheck]>
2016-09-22 22:31:17,441 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'ticketGrantingTicketCheck'>
2016-09-22 22:31:17,441 DEBUG [org.springframework.webflow.engine.DecisionState] - <Entering state 'gatewayRequestCheck' of flow 'login'>
2016-09-22 22:31:17,442 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@138f996 on = *, to = serviceAuthorizationCheck]>
2016-09-22 22:31:17,442 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'gatewayRequestCheck'>
2016-09-22 22:31:17,442 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'serviceAuthorizationCheck' of flow 'login'>
2016-09-22 22:31:17,443 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@16557fe expression = serviceAuthorizationCheck, resultExpression = [null]]>
2016-09-22 22:31:17,443 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.ServiceAuthorizationCheck@41dba0>
2016-09-22 22:31:17,446 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.ServiceAuthorizationCheck@41dba0; result = success>
2016-09-22 22:31:17,446 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@16557fe expression = serviceAuthorizationCheck, resultExpression = [null]]; result = success>
2016-09-22 22:31:17,446 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@1950931 on = *, to = initializeLoginForm]>
2016-09-22 22:31:17,446 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'serviceAuthorizationCheck'>
2016-09-22 22:31:17,447 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'initializeLoginForm' of flow 'login'>
2016-09-22 22:31:17,447 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@1ce528f expression = initializeLoginAction, resultExpression = [null]]>
2016-09-22 22:31:17,447 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,447 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.InitializeLoginAction@10826f8>
2016-09-22 22:31:17,448 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.InitializeLoginAction@10826f8; result = success>
2016-09-22 22:31:17,448 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,448 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@1ce528f expression = initializeLoginAction, resultExpression = [null]]; result = success>
2016-09-22 22:31:17,448 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@1b6e8e9 on = success, to = clientIp]>
2016-09-22 22:31:17,449 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'initializeLoginForm'>
2016-09-22 22:31:17,449 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'clientIp' of flow 'login'>
2016-09-22 22:31:17,449 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@5f8386 expression = ipBasedDispatcher, resultExpression = [null]]>
2016-09-22 22:31:17,449 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,450 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing fr.chpoitiers.cas.web.flow.NetworkBasedClientAction@d92576>
2016-09-22 22:31:17,450 DEBUG [fr.chpoitiers.cas.web.flow.NetworkBasedClientAction] - <Read Ip from request : 172.18.3.6 returning : interne>
2016-09-22 22:31:17,450 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing fr.chpoitiers.cas.web.flow.NetworkBasedClientAction@d92576; result = interne>
2016-09-22 22:31:17,450 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,451 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@5f8386 expression = ipBasedDispatcher, resultExpression = [null]]; result = interne>
2016-09-22 22:31:17,451 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@160ce7d on = interne, to = startSpnegoAuthenticate]>
2016-09-22 22:31:17,451 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'clientIp'>
2016-09-22 22:31:17,451 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'startSpnegoAuthenticate' of flow 'login'>
2016-09-22 22:31:17,452 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@75b2f4 expression = negociateSpnego, resultExpression = [null]]>
2016-09-22 22:31:17,452 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,452 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.SpnegoNegociateCredentialsAction@1623aa0>
2016-09-22 22:31:17,453 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.SpnegoNegociateCredentialsAction@1623aa0; result = success>
2016-09-22 22:31:17,453 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,453 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@75b2f4 expression = negociateSpnego, resultExpression = [null]]; result = success>
2016-09-22 22:31:17,455 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@10a9ce1 on = success, to = spnego]>
2016-09-22 22:31:17,455 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'startSpnegoAuthenticate'>
2016-09-22 22:31:17,455 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'spnego' of flow 'login'>
2016-09-22 22:31:17,455 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@80e64 expression = spnego, resultExpression = [null]]>
2016-09-22 22:31:17,456 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,456 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.SpnegoCredentialsAction@1f9e7fa>
2016-09-22 22:31:17,458 DEBUG [org.apereo.cas.authentication.RegisteredServiceAuthenticationHandlerResolver] - <Authentication handlers used for this transaction are [org.apereo.cas.authentication.handler.support.HttpBasedServiceCredentialsAuthenticationHandler@29629e, org.apereo.cas.adaptors.yubikey.YubiKeyAuthenticationHandler@79962d, org.apereo.cas.support.spnego.authentication.handler.support.JcifsSpnegoAuthenticationHandler@3987f2, org.apereo.cas.authentication.LdapAuthenticationHandler@7e0895]>
2016-09-22 22:31:17,555 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <JcifsSpnegoAuthenticationHandler successfully authenticated testuser>
2016-09-22 22:31:17,582 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <org.apereo.cas.support.spnego.authentication.principal.SpnegoPrincipalResolver@1156153 resolved testuser from testuser>
2016-09-22 22:31:17,585 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Final principal resolved for this authentication event is testuser>
2016-09-22 22:31:17,596 DEBUG [org.apereo.cas.authentication.AnyAuthenticationPolicy] - <Authentication policy is satisfied having found at least one authentication transactions>
2016-09-22 22:31:17,597 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Authenticated testuser with credentials [testuser].>
2016-09-22 22:31:17,599 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Attribute map for testuser: {affiliation=groupMembership, cn=commonName, displayName=displayName, uid=uid, username=testuser}>
2016-09-22 22:31:17,601 INFO [org.apereo.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: testuser
WHAT: Supplied credentials: [testuser]
ACTION: AUTHENTICATION_SUCCESS
APPLICATION: CAS
WHEN: Thu Sep 22 22:31:17 CEST 2016
CLIENT IP ADDRESS: 172.18.3.6
SERVER IP ADDRESS: testcas.example.com
=============================================================
>
2016-09-22 22:31:17,604 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationTransactionManager] - <Successful authentication; Collecting authentication result [org.apereo.cas.authentication.DefaultAuthentication@e063db46]>
2016-09-22 22:31:17,606 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collecting authentication history based on [1] authentication events>
2016-09-22 22:31:17,607 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Evaluating authentication principal [testuser] for inclusion in result>
2016-09-22 22:31:17,608 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected principal attributes [{uid=uid, cn=commonName, affiliation=groupMembership, displayName=displayName, username=testuser}] for inclusion in this result for principal [testuser]>
2016-09-22 22:31:17,610 WARN [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Authentication attribute [samlAuthenticationStatementAuthMethod] has no value and is not collected>
2016-09-22 22:31:17,611 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [authenticationMethod] -> [JcifsSpnegoAuthenticationHandler]>
2016-09-22 22:31:17,613 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [successfulAuthenticationHandlers] -> [[JcifsSpnegoAuthenticationHandler]]>
2016-09-22 22:31:17,614 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Finalized authentication attributes [{authenticationMethod=JcifsSpnegoAuthenticationHandler, successfulAuthenticationHandlers=[JcifsSpnegoAuthenticationHandler]}] for inclusion in this authentication result>
2016-09-22 22:31:17,615 DEBUG [org.apereo.cas.authentication.DefaultPrincipalElectionStrategy] - <Nominated [testuser] as the primary principal>
2016-09-22 22:31:17,617 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Determined primary authentication principal to be [testuser]>
2016-09-22 22:31:17,618 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected authentication attributes for this result are [{authenticationMethod=JcifsSpnegoAuthenticationHandler, successfulAuthenticationHandlers=[JcifsSpnegoAuthenticationHandler]}]>
2016-09-22 22:31:17,619 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Authentication result commenced at [2016-09-22T22:31:17.619+02:00[Europe/Paris]]>
2016-09-22 22:31:17,621 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Building an authentication result for authentication org.apereo.cas.authentication.DefaultAuthentication@d8109559 and service https://testcas.example.com/philippe/eclipse/testcas/www/cas5v3.php>
2016-09-22 22:31:17,625 DEBUG [org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository] - <DefaultPrincipalAttributesRepository will return the collection of attributes directly associated with the principal object which are [{affiliation=groupMembership, cn=commonName, displayName=displayName, uid=uid, username=testuser}]>
2016-09-22 22:31:17,626 DEBUG [org.apereo.cas.authentication.principal.cache.AbstractPrincipalAttributesRepository] - <Found [5] cached attributes for principal [testuser] that are {affiliation=groupMembership, cn=commonName, displayName=displayName, uid=uid, username=testuser}>
2016-09-22 22:31:17,629 INFO [org.apereo.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: testuser
WHAT: TGT-**********************************************ndlBMK02zm-devcas1
ACTION: TICKET_GRANTING_TICKET_CREATED
APPLICATION: CAS
WHEN: Thu Sep 22 22:31:17 CEST 2016
CLIENT IP ADDRESS: 172.18.3.6
SERVER IP ADDRESS: testcas.example.com
=============================================================
>
2016-09-22 22:31:17,633 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.SpnegoCredentialsAction@1f9e7fa; result = success>
2016-09-22 22:31:17,633 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,634 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@80e64 expression = spnego, resultExpression = [null]]; result = success>
2016-09-22 22:31:17,634 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@a45f25 on = success, to = sendTicketGrantingTicket]>
2016-09-22 22:31:17,635 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'spnego'>
2016-09-22 22:31:17,635 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'sendTicketGrantingTicket' of flow 'login'>
2016-09-22 22:31:17,635 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@22a3e2 expression = sendTicketGrantingTicketAction, resultExpression = [null]]>
2016-09-22 22:31:17,636 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,636 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.SendTicketGrantingTicketAction@60a33>
2016-09-22 22:31:17,638 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.SendTicketGrantingTicketAction@60a33; result = success>
2016-09-22 22:31:17,638 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,639 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@22a3e2 expression = sendTicketGrantingTicketAction, resultExpression = [null]]; result = success>
2016-09-22 22:31:17,639 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@1395ed9 on = *, to = serviceCheck]>
2016-09-22 22:31:17,645 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'sendTicketGrantingTicket'>
2016-09-22 22:31:17,645 DEBUG [org.springframework.webflow.engine.DecisionState] - <Entering state 'serviceCheck' of flow 'login'>
2016-09-22 22:31:17,646 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@1a17398 on = flowScope.service != null, to = generateServiceTicket]>
2016-09-22 22:31:17,646 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'serviceCheck'>
2016-09-22 22:31:17,646 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'generateServiceTicket' of flow 'login'>
2016-09-22 22:31:17,647 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@1be8d2d expression = generateServiceTicketAction, resultExpression = [null]]>
2016-09-22 22:31:17,647 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,647 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.GenerateServiceTicketAction@1c0770e>
2016-09-22 22:31:17,648 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collecting authentication history based on [1] authentication events>
2016-09-22 22:31:17,649 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Evaluating authentication principal [testuser] for inclusion in result>
2016-09-22 22:31:17,651 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected principal attributes [{uid=uid, cn=commonName, affiliation=groupMembership, displayName=displayName, username=testuser}] for inclusion in this result for principal [testuser]>
2016-09-22 22:31:17,652 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [authenticationMethod] -> [JcifsSpnegoAuthenticationHandler]>
2016-09-22 22:31:17,654 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [successfulAuthenticationHandlers] -> [[JcifsSpnegoAuthenticationHandler]]>
2016-09-22 22:31:17,655 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Finalized authentication attributes [{authenticationMethod=JcifsSpnegoAuthenticationHandler, successfulAuthenticationHandlers=[JcifsSpnegoAuthenticationHandler]}] for inclusion in this authentication result>
2016-09-22 22:31:17,656 DEBUG [org.apereo.cas.authentication.DefaultPrincipalElectionStrategy] - <Nominated [testuser] as the primary principal>
2016-09-22 22:31:17,658 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Determined primary authentication principal to be [testuser]>
2016-09-22 22:31:17,659 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected authentication attributes for this result are [{authenticationMethod=JcifsSpnegoAuthenticationHandler, successfulAuthenticationHandlers=[JcifsSpnegoAuthenticationHandler]}]>
2016-09-22 22:31:17,661 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Authentication result commenced at [2016-09-22T22:31:17.661+02:00[Europe/Paris]]>
2016-09-22 22:31:17,662 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Building an authentication result for authentication org.apereo.cas.authentication.DefaultAuthentication@ead71d9 and service https://testcas.example.com/philippe/eclipse/testcas/www/cas5v3.php>
2016-09-22 22:31:17,664 DEBUG [org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository] - <DefaultPrincipalAttributesRepository will return the collection of attributes directly associated with the principal object which are [{affiliation=groupMembership, cn=commonName, displayName=displayName, uid=uid, username=testuser}]>
2016-09-22 22:31:17,666 DEBUG [org.apereo.cas.authentication.principal.cache.AbstractPrincipalAttributesRepository] - <Found [5] cached attributes for principal [testuser] that are {affiliation=groupMembership, cn=commonName, displayName=displayName, uid=uid, username=testuser}>
2016-09-22 22:31:17,669 INFO [org.apereo.cas.CentralAuthenticationServiceImpl] - <Granted ticket [ST-4-NhAexJRg9TwPZ5ZWJH3M-devcas1] for service [https://testcas.example.com/philippe/eclipse/testcas/www/cas5v3.php] and principal [testuser]>
2016-09-22 22:31:17,671 INFO [org.apereo.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: testuser
WHAT: ST-4-NhAexJRg9TwPZ5ZWJH3M-devcas1 for https://testcas.example.com/philippe/eclipse/testcas/www/cas5v3.php
ACTION: SERVICE_TICKET_CREATED
APPLICATION: CAS
WHEN: Thu Sep 22 22:31:17 CEST 2016
CLIENT IP ADDRESS: 172.18.3.6
SERVER IP ADDRESS: testcas.example.com
=============================================================
>
2016-09-22 22:31:17,672 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.GenerateServiceTicketAction@1c0770e; result = success>
2016-09-22 22:31:17,673 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,673 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@1be8d2d expression = generateServiceTicketAction, resultExpression = [null]]; result = success>
2016-09-22 22:31:17,673 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@1d98f9e on = success, to = warn]>
2016-09-22 22:31:17,674 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'generateServiceTicket'>
2016-09-22 22:31:17,674 DEBUG [org.springframework.webflow.engine.DecisionState] - <Entering state 'warn' of flow 'login'>
2016-09-22 22:31:17,674 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@e74283 on = *, to = redirect]>
2016-09-22 22:31:17,675 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'warn'>
2016-09-22 22:31:17,675 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'redirect' of flow 'login'>
2016-09-22 22:31:17,676 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@1338437 expression = flowScope.service.getResponse(requestScope.serviceTicketId), resultExpression = requestScope.response]>
2016-09-22 22:31:17,676 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:31:17,677 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:31:17,677 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@1338437 expression = flowScope.service.getResponse(requestScope.serviceTicketId), resultExpression = requestScope.response]; result = success>
2016-09-22 22:31:17,678 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@195d5da on = *, to = postRedirectDecision]>
2016-09-22 22:31:17,678 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'redirect'>
2016-09-22 22:31:17,678 DEBUG [org.springframework.webflow.engine.DecisionState] - <Entering state 'postRedirectDecision' of flow 'login'>
2016-09-22 22:31:17,679 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@c1208a on = *, to = redirectView]>
2016-09-22 22:31:17,679 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'postRedirectDecision'>
2016-09-22 22:31:17,679 DEBUG [org.springframework.webflow.engine.EndState] - <Entering state 'redirectView' of flow 'login'>
2016-09-22 22:31:17,680 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.springframework.webflow.action.ViewFactoryActionAdapter@1cc485>
2016-09-22 22:31:17,680 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.springframework.webflow.action.ExternalRedirectAction@f6e885>
2016-09-22 22:31:17,681 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.springframework.webflow.action.ExternalRedirectAction@f6e885; result = success>
2016-09-22 22:31:17,681 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.springframework.webflow.action.ViewFactoryActionAdapter@1cc485; result = success>
2016-09-22 22:31:17,681 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,681 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,682 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,682 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,682 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,682 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,683 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,683 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,683 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,683 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,684 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,684 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,684 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,684 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the flow execution has ended>
2016-09-22 22:31:17,828 DEBUG [org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository] - <DefaultPrincipalAttributesRepository will return the collection of attributes directly associated with the principal object which are [{affiliation=groupMembership, cn=commonName, displayName=displayName, uid=uid, username=testuser}]>
2016-09-22 22:31:17,829 DEBUG [org.apereo.cas.authentication.principal.cache.AbstractPrincipalAttributesRepository] - <Found [5] cached attributes for principal [testuser] that are {affiliation=groupMembership, cn=commonName, displayName=displayName, uid=uid, username=testuser}>
2016-09-22 22:31:17,831 INFO [org.apereo.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: testuser
WHAT: ST-4-NhAexJRg9TwPZ5ZWJH3M-devcas1
ACTION: SERVICE_TICKET_VALIDATED
APPLICATION: CAS
WHEN: Thu Sep 22 22:31:17 CEST 2016
CLIENT IP ADDRESS: 172.16.10.177
SERVER IP ADDRESS: testcas.example.com
=============================================================
>
2016-09-22 22:31:17,833 DEBUG [org.apereo.cas.authentication.AuthenticationContextValidator] - <Attempting to match requested authentication context mfa-yubikey against []>
2016-09-22 22:31:17,834 DEBUG [org.apereo.cas.authentication.AuthenticationContextValidator] - <No authentication context could be determined based on authentication attribute authnContextClass>
2016-09-22 22:31:17,834 DEBUG [org.apereo.cas.authentication.AuthenticationContextValidator] - <No satisfied multifactor authentication providers are recorded in the current authentication context.>
Second pass :
2016-09-22 22:31:25,701 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <0 expired tickets removed.>
2016-09-22 22:31:25,702 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Finished ticket cleanup.>
2016-09-22 22:32:25,703 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <0 expired tickets removed.>
2016-09-22 22:32:25,704 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Finished ticket cleanup.>
2016-09-22 22:33:01,470 DEBUG [org.springframework.webflow.executor.FlowExecutorImpl] - <Launching new execution of flow 'login' with input map['service' -> 'https://testcas.example.com/philippe/eclipse/testcas/www/cas5v3.php']>
2016-09-22 22:33:01,470 DEBUG [org.springframework.webflow.definition.registry.FlowDefinitionRegistryImpl] - <Getting FlowDefinition with id 'login'>
2016-09-22 22:33:01,471 DEBUG [org.springframework.webflow.engine.Flow] - <Creating [FlowVariable@17f0abb name = 'credential', valueFactory = [BeanFactoryVariableValueFactory@7ad7ff type = UsernamePasswordCredential]]>
2016-09-22 22:33:01,479 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@12fb90f expression = initialFlowSetupAction, resultExpression = [null]]>
2016-09-22 22:33:01,479 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:33:01,480 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.InitialFlowSetupAction@2c1fd6>
2016-09-22 22:33:01,482 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.InitialFlowSetupAction@2c1fd6; result = success>
2016-09-22 22:33:01,484 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:33:01,485 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@12fb90f expression = initialFlowSetupAction, resultExpression = [null]]; result = success>
2016-09-22 22:33:01,485 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'initialAuthenticationRequestValidationCheck' of flow 'login'>
2016-09-22 22:33:01,485 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@1c95611 expression = initialAuthenticationRequestValidationAction, resultExpression = [null]]>
2016-09-22 22:33:01,485 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:33:01,486 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.InitialAuthenticationRequestValidationAction@18b8f92>
2016-09-22 22:33:01,500 DEBUG [org.apereo.cas.authentication.AuthenticationContextValidator] - <Attempting to match requested authentication context mfa-yubikey against []>
2016-09-22 22:33:01,501 DEBUG [org.apereo.cas.authentication.AuthenticationContextValidator] - <No authentication context could be determined based on authentication attribute authnContextClass>
2016-09-22 22:33:01,502 DEBUG [org.apereo.cas.authentication.AuthenticationContextValidator] - <No satisfied multifactor authentication providers are recorded in the current authentication context.>
2016-09-22 22:33:01,503 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.InitialAuthenticationRequestValidationAction@18b8f92; result = mfa-yubikey>
2016-09-22 22:33:01,503 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:33:01,503 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@1c95611 expression = initialAuthenticationRequestValidationAction, resultExpression = [null]]; result = mfa-yubikey>
2016-09-22 22:33:01,503 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@16205d0 on = mfa-yubikey, to = mfa-yubikey]>
2016-09-22 22:33:01,503 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'initialAuthenticationRequestValidationCheck'>
2016-09-22 22:33:01,503 DEBUG [org.springframework.webflow.engine.SubflowState] - <Entering state 'mfa-yubikey' of flow 'login'>
2016-09-22 22:33:01,503 DEBUG [org.springframework.webflow.definition.registry.FlowDefinitionRegistryImpl] - <Getting FlowDefinition with id 'mfa-yubikey'>
2016-09-22 22:33:01,503 DEBUG [org.springframework.webflow.engine.SubflowState] - <Calling subflow 'mfa-yubikey' with input map[[empty]]>
2016-09-22 22:33:01,503 DEBUG [org.springframework.webflow.engine.Flow] - <Creating [FlowVariable@db6ca7 name = 'credential', valueFactory = [BeanFactoryVariableValueFactory@1a0b4be type = YubiKeyCredential]]>
2016-09-22 22:33:01,504 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@1e5e15f expression = initialFlowSetupAction, resultExpression = [null]]>
2016-09-22 22:33:01,504 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:33:01,504 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.InitialFlowSetupAction@2c1fd6>
2016-09-22 22:33:01,505 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.InitialFlowSetupAction@2c1fd6; result = success>
2016-09-22 22:33:01,505 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@1e5e15f expression = initialFlowSetupAction, resultExpression = [null]]; result = success>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'initializeLoginForm' of flow 'mfa-yubikey'>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@200c10 expression = initializeLoginAction, resultExpression = [null]]>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.InitializeLoginAction@10826f8>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.InitializeLoginAction@10826f8; result = success>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@200c10 expression = initializeLoginAction, resultExpression = [null]]; result = success>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@39452e on = success, to = viewLoginFormYubiKey]>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'initializeLoginForm'>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.engine.ViewState] - <Entering state 'viewLoginFormYubiKey' of flow 'mfa-yubikey'>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [SetAction@1648d0c name = viewScope.principal, value = conversationScope.authentication.principal]>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2016-09-22 22:33:01,506 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [SetAction@1648d0c name = viewScope.principal, value = conversationScope.authentication.principal]; result = success>
2016-09-22 22:33:01,527 DEBUG [org.springframework.webflow.engine.ViewState] - <Rendering + [ServletMvcView@121f1f view = org.thymeleaf.spring4.view.ThymeleafView@1f3de5c]>
2016-09-22 22:33:01,527 DEBUG [org.springframework.webflow.engine.ViewState] - < Flash scope = map[[empty]]>
2016-09-22 22:33:01,527 DEBUG [org.springframework.webflow.engine.ViewState] - < Messages = [DefaultMessageContext@f70275 sourceMessages = map[[null] -> list[[empty]]]]>
2016-09-22 22:33:01,623 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the new state is 'viewLoginFormYubiKey' in flow 'mfa-yubikey'>
2016-09-22 22:33:01,626 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution. As a result, the new state is 'viewLoginFormYubiKey' in flow 'mfa-yubikey'>
2016-09-22 22:33:25,706 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <0 expired tickets removed.>
Any idea ?
Regards.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/6e14fc0f-fe47-5d79-7d4b-213425026bba%40ch-poitiers.fr.
For more options, visit https://groups.google.com/a/apereo.org/d/optout.
Misagh Moayyed
Sep 23, 2016, 1:36:11 PM9/23/16
to cas-...@apereo.org
Second test :
- SPNEGO
- yubikey
=> works oddly : my client service page uses phpCAS, on first pass I get an "Authentication Error, try again", If I click on "try again", then yubikey token is asked, and after validation, I'm logged to the application.
I suspect that transition on success after SPNEGO to be incorrect. It's hardcoded to CasWebflowConstants.TRANSITION_ID_SEND_TICKET_GRANTING_TICKET, but MFA shoud be inspected before sending TGC, shouldn't it ?
It should, yes. Do submit a bug plz. I suspect MFA only takes into account interactive authn, which is something that needs to be fixed.
Philippe MARASSE
Sep 26, 2016, 11:26:38 AM9/26/16
to cas-...@apereo.org
Hello,
Thanks for your answer, I've opened this issue : https://github.com/apereo/cas/issues/2018
Regards
Thanks for your answer, I've opened this issue : https://github.com/apereo/cas/issues/2018
Regards
--
You received this message because you are subscribed to the Google Groups "CAS Community" group.
To unsubscribe from this group and stop receiving emails from it, send an email to cas-user+u...@apereo.org.
To post to this group, send email to cas-...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/cas-user/.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/etPan.57e567f8.1ae214b4.2e6e%40unicon.net.
For more options, visit https://groups.google.com/a/apereo.org/d/optout.
Reply all
Reply to author
Forward
0 new messages