Here is the full output of the CAS logs for each part of the login request, with my IP and password removed from the logs.
===== Initial request to /cas/login ==> /var/log/httpd/ssl_access_log <== USER_IP - - [23/Jan/2012:13:23:50 -0400] "GET /cas/login?service=https%3a%2f%2fwebtest.its.unb.ca%2fcas-dev%2findex.cgi HTTP/1.1" 200 6392 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_7_2) AppleWebKit/535.11 (KHTML, like Gecko) Chrome/17.0.963.38 Safari/535.11" ==> /var/log/tomcat6/cas.log <== 2012-01-23 13:23:50,957 DEBUG [org.springframework.web.servlet.DispatcherServlet] - DispatcherServlet with name 'cas' determining Last-Modified value for [/cas/login] 2012-01-23 13:23:50,957 DEBUG [org.springframework.web.servlet.handler.SimpleUrlHandlerMapping] - Mapping [/login] to handler 'org.springframework.webflow.executor.mvc.FlowController@1d87b360' 2012-01-23 13:23:50,958 DEBUG [org.springframework.web.servlet.DispatcherServlet] - Last-Modified value for [/cas/login] is: -1 2012-01-23 13:23:50,958 DEBUG [org.springframework.web.servlet.DispatcherServlet] - DispatcherServlet with name 'cas' processing request for [/cas/login] 2012-01-23 13:23:50,958 DEBUG [org.springframework.webflow.executor.support.FlowRequestHandler] - Request initiated by [ServletExternalContext@241ee2c5 requestParameterMap = map['service' -> 'https://webtest.its.unb.ca/cas-dev/index.cgi']] 2012-01-23 13:23:50,958 DEBUG [org.springframework.webflow.executor.FlowExecutorImpl] - Launching flow execution for flow definition 'login-webflow' 2012-01-23 13:23:50,958 DEBUG [org.springframework.webflow.definition.registry.FlowDefinitionRegistryImpl] - Getting flow definition with id 'login-webflow' 2012-01-23 13:23:50,958 DEBUG [org.springframework.webflow.engine.builder.RefreshableFlowDefinitionHolder] - Calculating last modified timestamp for flow definition resource 'ServletContext resource [/WEB-INF/login-webflow.xml]' 2012-01-23 13:23:50,958 DEBUG [org.springframework.webflow.engine.impl.FlowExecutionImplFactory] - Creating flow execution for flow definition with id 'login-webflow' 2012-01-23 13:23:50,958 DEBUG [org.springframework.webflow.engine.impl.FlowExecutionImpl] - Created new execution of flow 'login-webflow' 2012-01-23 13:23:50,959 DEBUG [org.springframework.webflow.engine.impl.FlowExecutionImpl] - Starting execution with input 'map['service' -> 'https://webtest.its.unb.ca/cas-dev/index.cgi']' 2012-01-23 13:23:50,959 DEBUG [org.springframework.webflow.engine.impl.RequestControlContextImpl] - Activating new session for flow 'login-webflow' in state 'initialFlowSetup' with input map['service' -> 'https://webtest.its.unb.ca/cas-dev/index.cgi'] 2012-01-23 13:23:50,959 DEBUG [org.springframework.webflow.engine.impl.FlowExecutionImpl] - Starting [FlowSessionImpl@67ba0609 flow = 'login-webflow', state = [null], scope = map[[empty]], flashMap = map[[empty]], status = Starting] 2012-01-23 13:23:50,959 DEBUG [org.springframework.webflow.engine.ActionState] - Entering state 'initialFlowSetup' of flow 'login-webflow' 2012-01-23 13:23:50,959 DEBUG [org.springframework.webflow.engine.ActionExecutor] - Executing [AnnotatedAction@c6a26b targetAction = org.jasig.cas.web.flow.InitialFlowSetupAction@70d11f32, attributes = map[[empty]]] in state 'initialFlowSetup' of flow 'login-webflow' 2012-01-23 13:23:50,959 DEBUG [org.jasig.cas.web.support.CasArgumentExtractor] - Extractor generated service for: https://webtest.its.unb.ca/cas-dev/index.cgi 2012-01-23 13:23:50,959 DEBUG [org.springframework.webflow.engine.impl.RequestControlContextImpl] - Signaling event 'success' in state 'initialFlowSetup' of flow 'login-webflow' 2012-01-23 13:23:50,959 DEBUG [org.springframework.webflow.engine.Transition] - Executing [Transition@3d0bc85 on = [eventId = 'success'], to = ticketGrantingTicketExistsCheck] out of state 'initialFlowSetup' 2012-01-23 13:23:50,959 DEBUG [org.springframework.webflow.engine.DecisionState] - Entering state 'ticketGrantingTicketExistsCheck' of flow 'login-webflow' 2012-01-23 13:23:50,960 DEBUG [org.springframework.webflow.engine.Transition] - Executing [Transition@53adceb8 on = *, to = gatewayRequestCheck] out of state 'ticketGrantingTicketExistsCheck' 2012-01-23 13:23:50,960 DEBUG [org.springframework.webflow.engine.DecisionState] - Entering state 'gatewayRequestCheck' of flow 'login-webflow' 2012-01-23 13:23:50,960 DEBUG [org.springframework.webflow.engine.Transition] - Executing [Transition@6c74b024 on = *, to = viewLoginForm] out of state 'gatewayRequestCheck' 2012-01-23 13:23:50,960 DEBUG [org.springframework.webflow.engine.ViewState] - Entering state 'viewLoginForm' of flow 'login-webflow' 2012-01-23 13:23:50,961 DEBUG [org.springframework.webflow.engine.ActionExecutor] - Executing [AnnotatedAction@60d8431c targetAction = org.jasig.cas.web.flow.AuthenticationViaFormAction@161e14f0, attributes = map['method' -> 'setupForm']] in state 'viewLoginForm' of flow 'login-webflow' 2012-01-23 13:23:50,961 DEBUG [org.springframework.webflow.engine.ActionExecutor] - Executing [AnnotatedAction@2dcc5af0 targetAction = org.jasig.cas.web.flow.AuthenticationViaFormAction@161e14f0, attributes = map['method' -> 'referenceData']] in state 'viewLoginForm' of flow 'login-webflow' 2012-01-23 13:23:50,961 DEBUG [org.springframework.webflow.engine.Transition] - Completed execution of [Transition@6c74b024 on = *, to = viewLoginForm], as a result the new state is 'viewLoginForm' in flow 'login-webflow' 2012-01-23 13:23:50,961 DEBUG [org.springframework.webflow.engine.Transition] - Completed execution of [Transition@53adceb8 on = *, to = gatewayRequestCheck], as a result the new state is 'viewLoginForm' in flow 'login-webflow' 2012-01-23 13:23:50,961 DEBUG [org.springframework.webflow.engine.Transition] - Completed execution of [Transition@3d0bc85 on = [eventId = 'success'], to = ticketGrantingTicketExistsCheck], as a result the new state is 'viewLoginForm' in flow 'login-webflow' 2012-01-23 13:23:50,961 DEBUG [org.springframework.webflow.engine.impl.FlowExecutionImpl] - Paused to render 'casLoginView' [[service, commandName, credentials, currentFormObject, warnCookieValue, ticketGrantingTicketId, org.springframework.validation.BindException.currentFormObject, org.springframework.validation.BindException.credentials]] and wait for user input 2012-01-23 13:23:50,961 DEBUG [org.springframework.webflow.conversation.impl.SessionBindingConversationManager] - Beginning conversation [ConversationParameters@65e26e12 name = 'login-webflow']; unique conversation id = E24887C6-9565-C375-A8C5-33FA66473A73 2012-01-23 13:23:50,962 DEBUG [org.springframework.webflow.execution.repository.continuation.ContinuationFlowExecutionRepository] - Generated new key for flow execution '[FlowExecutionImpl@74a893ff flow = 'login-webflow', flowSessions = list[[FlowSessionImpl@67ba0609 flow = 'login-webflow', state = 'viewLoginForm', scope = map['service' -> https://webtest.its.unb.ca/cas-dev/index.cgi, 'credentials' -> [username: null], 'currentFormObject' -> [username: null], 'warnCookieValue' -> false, 'ticketGrantingTicketId' -> [null]], flashMap = map['org.springframework.validation.BindException.currentFormObject' -> org.springframework.validation.BindException: org.springframework.validation.BeanPropertyBindingResult: 0 errors, 'org.springframework.validation.BindException.credentials' -> org.springframework.validation.BindException: org.springframework.validation.BeanPropertyBindingResult: 0 errors], status = Paused]]]': '_cE24887C6-9565-C375-A8C5-33FA66473A73_k624F3F4A-1285-A74C-817E-BCD7C80D0D7D' 2012-01-23 13:23:50,962 DEBUG [org.springframework.webflow.conversation.impl.SessionBindingConversationManager] - Getting conversation E24887C6-9565-C375-A8C5-33FA66473A73 2012-01-23 13:23:50,962 DEBUG [org.springframework.webflow.conversation.impl.SessionBindingConversationManager] - Locking conversation E24887C6-9565-C375-A8C5-33FA66473A73 2012-01-23 13:23:50,962 DEBUG [org.springframework.webflow.execution.repository.continuation.ContinuationFlowExecutionRepository] - Putting flow execution '[FlowExecutionImpl@74a893ff flow = 'login-webflow', flowSessions = list[[FlowSessionImpl@67ba0609 flow = 'login-webflow', state = 'viewLoginForm', scope = map['service' -> https://webtest.its.unb.ca/cas-dev/index.cgi, 'credentials' -> [username: null], 'currentFormObject' -> [username: null], 'warnCookieValue' -> false, 'ticketGrantingTicketId' -> [null]], flashMap = map['org.springframework.validation.BindException.currentFormObject' -> org.springframework.validation.BindException: org.springframework.validation.BeanPropertyBindingResult: 0 errors, 'org.springframework.validation.BindException.credentials' -> org.springframework.validation.BindException: org.springframework.validation.BeanPropertyBindingResult: 0 errors], status = Paused]]]' into repository with key '_cE24887C6-9565-C375-A8C5-33FA66473A73_k624F3F4A-1285-A74C-817E-BCD7C80D0D7D' 2012-01-23 13:23:50,962 DEBUG [org.springframework.webflow.conversation.impl.SessionBindingConversationManager] - Getting conversation E24887C6-9565-C375-A8C5-33FA66473A73 2012-01-23 13:23:50,962 DEBUG [org.springframework.webflow.conversation.impl.SessionBindingConversationManager] - Putting conversation attribute 'continuationGroup' with value org.springframework.webflow.execution.repository.continuation.FlowExecutionContinuationGroup@678c862e 2012-01-23 13:23:51,003 DEBUG [org.springframework.webflow.execution.repository.continuation.ContinuationFlowExecutionRepository] - Adding new continuation to group with id 624F3F4A-1285-A74C-817E-BCD7C80D0D7D 2012-01-23 13:23:51,003 DEBUG [org.springframework.webflow.conversation.impl.SessionBindingConversationManager] - Getting conversation E24887C6-9565-C375-A8C5-33FA66473A73 2012-01-23 13:23:51,003 DEBUG [org.springframework.webflow.conversation.impl.SessionBindingConversationManager] - Putting conversation attribute 'scope' with value map[[empty]] 2012-01-23 13:23:51,004 DEBUG [org.springframework.webflow.conversation.impl.SessionBindingConversationManager] - Unlocking conversation E24887C6-9565-C375-A8C5-33FA66473A73 2012-01-23 13:23:51,004 DEBUG [org.springframework.webflow.executor.support.FlowRequestHandler] - Returning [launch] [ResponseInstruction@3344c133 flowExecutionKey = '_cE24887C6-9565-C375-A8C5-33FA66473A73_k624F3F4A-1285-A74C-817E-BCD7C80D0D7D', viewSelection = 'casLoginView' [[service, commandName, credentials, currentFormObject, warnCookieValue, ticketGrantingTicketId, org.springframework.validation.BindException.currentFormObject, org.springframework.validation.BindException.credentials]], flowExecutionContext = [FlowExecutionImpl@74a893ff flow = 'login-webflow', flowSessions = list[[FlowSessionImpl@67ba0609 flow = 'login-webflow', state = 'viewLoginForm', scope = map['service' -> https://webtest.its.unb.ca/cas-dev/index.cgi, 'credentials' -> [username: null], 'currentFormObject' -> [username: null], 'warnCookieValue' -> false, 'ticketGrantingTicketId' -> [null]], flashMap = map['org.springframework.validation.BindException.currentFormObject' -> org.springframework.validation.BindException: org.springframework.validation.BeanPropertyBindingResult: 0 errors, 'org.springframework.validation.BindException.credentials' -> org.springframework.validation.BindException: org.springframework.validation.BeanPropertyBindingResult: 0 errors], status = Paused]]]] 2012-01-23 13:23:51,004 DEBUG [org.springframework.web.servlet.DispatcherServlet] - Rendering view [org.springframework.web.servlet.view.JstlView: name 'casLoginView'; URL [/WEB-INF/view/jsp/default/ui/casLoginView.jsp]] in DispatcherServlet with name 'cas' 2012-01-23 13:23:51,004 DEBUG [org.springframework.web.servlet.view.JstlView] - Added model object 'flowExecutionContext' of type [org.springframework.webflow.engine.impl.FlowExecutionImpl] to request in view with name 'casLoginView' 2012-01-23 13:23:51,004 DEBUG [org.springframework.web.servlet.view.JstlView] - Added model object 'service' of type [org.jasig.cas.authentication.principal.SimpleWebApplicationServiceImpl] to request in view with name 'casLoginView' 2012-01-23 13:23:51,004 DEBUG [org.springframework.web.servlet.view.JstlView] - Added model object 'commandName' of type [java.lang.String] to request in view with name 'casLoginView' 2012-01-23 13:23:51,004 DEBUG [org.springframework.web.servlet.view.JstlView] - Added model object 'credentials' of type [org.jasig.cas.authentication.principal.UsernamePasswordCredentials] to request in view with name 'casLoginView' 2012-01-23 13:23:51,004 DEBUG [org.springframework.web.servlet.view.JstlView] - Added model object 'currentFormObject' of type [org.jasig.cas.authentication.principal.UsernamePasswordCredentials] to request in view with name 'casLoginView' 2012-01-23 13:23:51,005 DEBUG [org.springframework.web.servlet.view.JstlView] - Added model object 'flowExecutionKey' of type [java.lang.String] to request in view with name 'casLoginView' 2012-01-23 13:23:51,005 DEBUG [org.springframework.web.servlet.view.JstlView] - Added model object 'warnCookieValue' of type [java.lang.Boolean] to request in view with name 'casLoginView' 2012-01-23 13:23:51,005 DEBUG [org.springframework.web.servlet.view.JstlView] - Removed model object 'ticketGrantingTicketId' from request in view with name 'casLoginView' 2012-01-23 13:23:51,005 DEBUG [org.springframework.web.servlet.view.JstlView] - Added model object 'org.springframework.validation.BindException.currentFormObject' of type [org.springframework.validation.BindException] to request in view with name 'casLoginView' 2012-01-23 13:23:51,005 DEBUG [org.springframework.web.servlet.view.JstlView] - Added model object 'org.springframework.validation.BindException.credentials' of type [org.springframework.validation.BindException] to request in view with name 'casLoginView' 2012-01-23 13:23:51,005 DEBUG [org.springframework.web.servlet.view.JstlView] - Forwarding to resource [/WEB-INF/view/jsp/default/ui/casLoginView.jsp] in InternalResourceView 'casLoginView' 2012-01-23 13:23:51,007 DEBUG [org.springframework.web.servlet.DispatcherServlet] - Successfully completed request ===== Authentication & Redirection to service ==> /var/log/httpd/ssl_access_log <== USER_IP - - [23/Jan/2012:13:24:01 -0400] "POST /cas/login;jsessionid=5A7FF135E4B4DCE94C52CB15AC5CB246?service=https%3a%2f%2fwebtest.its.unb.ca%2fcas-dev%2findex.cgi HTTP/1.1" 302 - "https://fortran.its.unb.ca/cas/login?service=https%3a%2f%2fwebtest.its.unb.ca%2fcas-dev%2findex.cgi"; "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_7_2) AppleWebKit/535.11 (KHTML, like Gecko) Chrome/17.0.963.38 Safari/535.11" ==> /var/log/tomcat6/cas.log <== 2012-01-23 13:24:01,165 DEBUG [org.springframework.web.servlet.DispatcherServlet] - DispatcherServlet with name 'cas' processing request for [/cas/login] 2012-01-23 13:24:01,165 DEBUG [org.springframework.web.servlet.handler.SimpleUrlHandlerMapping] - Mapping [/login] to handler 'org.springframework.webflow.executor.mvc.FlowController@1d87b360' 2012-01-23 13:24:01,166 DEBUG [org.springframework.webflow.executor.support.FlowRequestHandler] - Request initiated by [ServletExternalContext@9482aa9 requestParameterMap = map['lt' -> '_cE24887C6-9565-C375-A8C5-33FA66473A73_k624F3F4A-1285-A74C-817E-BCD7C80D0D7D', 'service' -> 'https://webtest.its.unb.ca/cas-dev/index.cgi', '_eventId' -> 'submit', 'password' -> '*****', 'submit' -> 'Log In', 'username' -> 'jgoguen']] 2012-01-23 13:24:01,166 DEBUG [org.springframework.webflow.executor.FlowExecutorImpl] - Resuming flow execution with key '_cE24887C6-9565-C375-A8C5-33FA66473A73_k624F3F4A-1285-A74C-817E-BCD7C80D0D7D' on user event 'submit' 2012-01-23 13:24:01,166 DEBUG [org.springframework.webflow.execution.repository.continuation.ContinuationFlowExecutionRepository] - Parsed encoded flow execution key '_cE24887C6-9565-C375-A8C5-33FA66473A73_k624F3F4A-1285-A74C-817E-BCD7C80D0D7D', extracted conversation id 'E24887C6-9565-C375-A8C5-33FA66473A73' and continuation id '624F3F4A-1285-A74C-817E-BCD7C80D0D7D' 2012-01-23 13:24:01,166 DEBUG [org.springframework.webflow.conversation.impl.SessionBindingConversationManager] - Getting conversation E24887C6-9565-C375-A8C5-33FA66473A73 2012-01-23 13:24:01,167 DEBUG [org.springframework.webflow.conversation.impl.SessionBindingConversationManager] - Locking conversation E24887C6-9565-C375-A8C5-33FA66473A73 2012-01-23 13:24:01,167 DEBUG [org.springframework.webflow.execution.repository.continuation.ContinuationFlowExecutionRepository] - Getting flow execution with key '_cE24887C6-9565-C375-A8C5-33FA66473A73_k624F3F4A-1285-A74C-817E-BCD7C80D0D7D' 2012-01-23 13:24:01,167 DEBUG [org.springframework.webflow.conversation.impl.SessionBindingConversationManager] - Getting conversation E24887C6-9565-C375-A8C5-33FA66473A73 2012-01-23 13:24:01,177 DEBUG [org.springframework.webflow.conversation.impl.SessionBindingConversationManager] - Getting conversation E24887C6-9565-C375-A8C5-33FA66473A73 2012-01-23 13:24:01,177 DEBUG [org.springframework.webflow.definition.registry.FlowDefinitionRegistryImpl] - Getting flow definition with id 'login-webflow' 2012-01-23 13:24:01,177 DEBUG [org.springframework.webflow.engine.builder.RefreshableFlowDefinitionHolder] - Calculating last modified timestamp for flow definition resource 'ServletContext resource [/WEB-INF/login-webflow.xml]' 2012-01-23 13:24:01,177 DEBUG [org.springframework.webflow.engine.impl.FlowExecutionImpl] - Resuming execution on user event 'submit' 2012-01-23 13:24:01,178 DEBUG [org.springframework.webflow.engine.impl.RequestControlContextImpl] - Signaling event 'submit' in state 'viewLoginForm' of flow 'login-webflow' 2012-01-23 13:24:01,178 DEBUG [org.springframework.webflow.engine.Transition] - Executing [Transition@30a14e84 on = [eventId = 'submit'], to = bindAndValidate] out of state 'viewLoginForm' 2012-01-23 13:24:01,178 DEBUG [org.springframework.webflow.engine.ActionState] - Entering state 'bindAndValidate' of flow 'login-webflow' 2012-01-23 13:24:01,178 DEBUG [org.springframework.webflow.engine.ActionExecutor] - Executing [AnnotatedAction@3c626028 targetAction = org.jasig.cas.web.flow.AuthenticationViaFormAction@161e14f0, attributes = map[[empty]]] in state 'bindAndValidate' of flow 'login-webflow' 2012-01-23 13:24:01,179 DEBUG [org.springframework.webflow.engine.impl.RequestControlContextImpl] - Signaling event 'success' in state 'bindAndValidate' of flow 'login-webflow' 2012-01-23 13:24:01,179 DEBUG [org.springframework.webflow.engine.Transition] - Executing [Transition@653cca0e on = [eventId = 'success'], to = submit] out of state 'bindAndValidate' 2012-01-23 13:24:01,179 DEBUG [org.springframework.webflow.engine.ActionState] - Entering state 'submit' of flow 'login-webflow' 2012-01-23 13:24:01,180 DEBUG [org.springframework.webflow.engine.ActionExecutor] - Executing [AnnotatedAction@79f5910e targetAction = org.jasig.cas.web.flow.AuthenticationViaFormAction@161e14f0, attributes = map['method' -> 'submit']] in state 'submit' of flow 'login-webflow' 2012-01-23 13:24:01,180 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - Creating new transaction with name [org.jasig.cas.CentralAuthenticationService.createTicketGrantingTicket]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT 2012-01-23 13:24:01,180 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@34945d2d] for JPA transaction 2012-01-23 13:24:01,182 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - Exposing JPA transaction as JDBC transaction [SimpleConnectionHandle: com.mchange.v2.c3p0.impl.NewProxyConnection@57507544] 2012-01-23 13:24:01,183 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl] - Attempting to create TicketGrantingTicket for [username: jgoguen] 2012-01-23 13:24:01,183 INFO [org.jasig.cas.authentication.AuthenticationManagerImpl] - AuthenticationHandler: org.jasig.cas.adaptors.generic.FileAuthenticationHandler failed to authenticate the user which provided the following credentials: [username: jgoguen] 2012-01-23 13:24:01,238 DEBUG [org.springframework.ldap.core.support.AbstractContextSource] - Got Ldap context on server 'ldaps://ldap.unb.ca' 2012-01-23 13:24:01,241 DEBUG [org.jasig.cas.adaptors.ldap.BindLdapAuthenticationHandler] - Performing LDAP bind with credential: LDAP_USER_DN 2012-01-23 13:24:01,288 DEBUG [org.springframework.ldap.core.support.AbstractContextSource] - Got Ldap context on server 'ldaps://ldap.unb.ca' 2012-01-23 13:24:01,289 INFO [org.jasig.cas.authentication.AuthenticationManagerImpl] - AuthenticationHandler: org.jasig.cas.adaptors.ldap.BindLdapAuthenticationHandler successfully authenticated the user which provided the following credentials: [username: jgoguen] 2012-01-23 13:24:01,289 DEBUG [org.jasig.cas.authentication.principal.UsernamePasswordCredentialsToPrincipalResolver] - Attempting to resolve a principal... 2012-01-23 13:24:01,289 DEBUG [org.jasig.cas.authentication.principal.UsernamePasswordCredentialsToPrincipalResolver] - Creating SimplePrincipal for [jgoguen] 2012-01-23 13:24:01,290 DEBUG [org.springframework.jdbc.datasource.DataSourceTransactionManager] - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_READ_COMMITTED,timeout_5 2012-01-23 13:24:01,290 DEBUG [org.springframework.jdbc.datasource.DataSourceTransactionManager] - Acquired Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@1235047f] for JDBC transaction 2012-01-23 13:24:01,290 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils] - Changing isolation level of JDBC Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@1235047f] to 2 2012-01-23 13:24:01,290 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - Added ticket [TGT-2-AFXxosgXr7WiAHRmYac5fhUGxt42hvOyakbqGGgODbX2kiSv2G-cas] to registry. 2012-01-23 13:24:01,290 DEBUG [org.springframework.jdbc.datasource.DataSourceTransactionManager] - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_READ_COMMITTED,timeout_5 2012-01-23 13:24:01,290 DEBUG [org.springframework.jdbc.datasource.DataSourceTransactionManager] - Acquired Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@72810768] for JDBC transaction 2012-01-23 13:24:01,290 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils] - Changing isolation level of JDBC Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@72810768] to 2 2012-01-23 13:24:01,292 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - Initiating transaction commit 2012-01-23 13:24:01,292 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl@34945d2d] 2012-01-23 13:24:01,293 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - Closing JPA EntityManager [org.hibernate.ejb.EntityManagerImpl@34945d2d] after transaction 2012-01-23 13:24:01,293 DEBUG [org.springframework.orm.jpa.EntityManagerFactoryUtils] - Closing JPA EntityManager 2012-01-23 13:24:01,293 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - Attempting to retrieve ticket [TGT-2-AFXxosgXr7WiAHRmYac5fhUGxt42hvOyakbqGGgODbX2kiSv2G-cas] 2012-01-23 13:24:01,293 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - Ticket [TGT-2-AFXxosgXr7WiAHRmYac5fhUGxt42hvOyakbqGGgODbX2kiSv2G-cas] found in registry. 2012-01-23 13:24:01,294 DEBUG [org.jasig.cas.web.support.CookieRetrievingCookieGenerator] - Removed cookie with name [CASPRIVACY] 2012-01-23 13:24:01,294 DEBUG [org.springframework.webflow.engine.impl.RequestControlContextImpl] - Signaling event 'success' in state 'submit' of flow 'login-webflow' 2012-01-23 13:24:01,294 DEBUG [org.springframework.webflow.engine.Transition] - Executing [Transition@4aad8dbc on = [eventId = 'success'], to = sendTicketGrantingTicket] out of state 'submit' 2012-01-23 13:24:01,294 DEBUG [org.springframework.webflow.engine.ActionState] - Entering state 'sendTicketGrantingTicket' of flow 'login-webflow' 2012-01-23 13:24:01,294 DEBUG [org.springframework.webflow.engine.ActionExecutor] - Executing [AnnotatedAction@483457f1 targetAction = org.jasig.cas.web.flow.SendTicketGrantingTicketAction@6479b43f, attributes = map[[empty]]] in state 'sendTicketGrantingTicket' of flow 'login-webflow' 2012-01-23 13:24:01,294 DEBUG [org.jasig.cas.web.support.CookieRetrievingCookieGenerator] - Added cookie with name [UNBCAS] and value [TGT-2-AFXxosgXr7WiAHRmYac5fhUGxt42hvOyakbqGGgODbX2kiSv2G-cas] 2012-01-23 13:24:01,294 DEBUG [org.springframework.webflow.engine.impl.RequestControlContextImpl] - Signaling event 'success' in state 'sendTicketGrantingTicket' of flow 'login-webflow' 2012-01-23 13:24:01,294 DEBUG [org.springframework.webflow.engine.Transition] - Executing [Transition@7228c7a1 on = [eventId = 'success'], to = serviceCheck] out of state 'sendTicketGrantingTicket' 2012-01-23 13:24:01,294 DEBUG [org.springframework.webflow.engine.DecisionState] - Entering state 'serviceCheck' of flow 'login-webflow' 2012-01-23 13:24:01,294 DEBUG [org.springframework.webflow.engine.Transition] - Executing [Transition@22a79c31 on = flowScope.service != null, to = generateServiceTicket] out of state 'serviceCheck' 2012-01-23 13:24:01,294 DEBUG [org.springframework.webflow.engine.ActionState] - Entering state 'generateServiceTicket' of flow 'login-webflow' 2012-01-23 13:24:01,294 DEBUG [org.springframework.webflow.engine.ActionExecutor] - Executing [AnnotatedAction@29ff66bd targetAction = org.jasig.cas.web.flow.GenerateServiceTicketAction@3eb217d5, attributes = map[[empty]]] in state 'generateServiceTicket' of flow 'login-webflow' 2012-01-23 13:24:01,295 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - Creating new transaction with name [org.jasig.cas.CentralAuthenticationService.grantServiceTicket]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT 2012-01-23 13:24:01,295 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@569083c1] for JPA transaction 2012-01-23 13:24:01,295 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - Exposing JPA transaction as JDBC transaction [SimpleConnectionHandle: com.mchange.v2.c3p0.impl.NewProxyConnection@7a9eb4a1] 2012-01-23 13:24:01,296 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - Attempting to retrieve ticket [TGT-2-AFXxosgXr7WiAHRmYac5fhUGxt42hvOyakbqGGgODbX2kiSv2G-cas] 2012-01-23 13:24:01,296 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - Ticket [TGT-2-AFXxosgXr7WiAHRmYac5fhUGxt42hvOyakbqGGgODbX2kiSv2G-cas] found in registry. 2012-01-23 13:24:01,296 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - Added ticket [ST-2-aeTTN5A7qDb7oAcqilHJ-cas] to registry. 2012-01-23 13:24:01,296 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] - Granted service ticket [ST-2-aeTTN5A7qDb7oAcqilHJ-cas] for service [https://webtest.its.unb.ca/cas-dev/index.cgi] for user [jgoguen] 2012-01-23 13:24:01,296 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - Attempting to retrieve ticket [TGT-2-AFXxosgXr7WiAHRmYac5fhUGxt42hvOyakbqGGgODbX2kiSv2G-cas] 2012-01-23 13:24:01,296 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - Ticket [TGT-2-AFXxosgXr7WiAHRmYac5fhUGxt42hvOyakbqGGgODbX2kiSv2G-cas] found in registry. 2012-01-23 13:24:01,297 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - Initiating transaction commit 2012-01-23 13:24:01,297 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl@569083c1] 2012-01-23 13:24:01,298 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - Closing JPA EntityManager [org.hibernate.ejb.EntityManagerImpl@569083c1] after transaction 2012-01-23 13:24:01,298 DEBUG [org.springframework.orm.jpa.EntityManagerFactoryUtils] - Closing JPA EntityManager 2012-01-23 13:24:01,298 DEBUG [org.springframework.webflow.engine.impl.RequestControlContextImpl] - Signaling event 'success' in state 'generateServiceTicket' of flow 'login-webflow' 2012-01-23 13:24:01,298 DEBUG [org.springframework.webflow.engine.Transition] - Executing [Transition@1ccdf3c2 on = [eventId = 'success'], to = warn] out of state 'generateServiceTicket' 2012-01-23 13:24:01,298 DEBUG [org.springframework.webflow.engine.DecisionState] - Entering state 'warn' of flow 'login-webflow' 2012-01-23 13:24:01,298 DEBUG [org.springframework.webflow.engine.Transition] - Executing [Transition@153e5454 on = *, to = PasswordWarningCheck] out of state 'warn' 2012-01-23 13:24:01,298 DEBUG [org.springframework.webflow.engine.ActionState] - Entering state 'PasswordWarningCheck' of flow 'login-webflow' 2012-01-23 13:24:01,298 DEBUG [org.springframework.webflow.engine.ActionExecutor] - Executing [AnnotatedAction@2f1261b1 targetAction = org.jasig.cas.web.flow.PasswordWarningCheckAction@5fcbc39b, attributes = map[[empty]]] in state 'PasswordWarningCheck' of flow 'login-webflow' 2012-01-23 13:24:01,298 DEBUG [org.springframework.webflow.engine.impl.RequestControlContextImpl] - Signaling event 'success' in state 'PasswordWarningCheck' of flow 'login-webflow' 2012-01-23 13:24:01,298 DEBUG [org.springframework.webflow.engine.Transition] - Executing [Transition@3a97263f on = [eventId = 'success'], to = redirect] out of state 'PasswordWarningCheck' 2012-01-23 13:24:01,299 DEBUG [org.springframework.webflow.engine.EndState] - Entering state 'redirect' of flow 'login-webflow' 2012-01-23 13:24:01,299 DEBUG [org.springframework.webflow.engine.impl.RequestControlContextImpl] - Ending active session [FlowSessionImpl@6da1446d flow = 'login-webflow', state = 'redirect', scope = map['principal' -> jgoguen, 'service' -> https://webtest.its.unb.ca/cas-dev/index.cgi, 'credentials' -> [username: jgoguen], 'currentFormObject' -> [username: jgoguen], 'warnCookieValue' -> false, 'ticketGrantingTicketId' -> [null]], flashMap = map['org.springframework.validation.BindException.currentFormObject' -> org.springframework.validation.BindException: org.springframework.validation.BeanPropertyBindingResult: 0 errors, 'org.springframework.validation.BindException.credentials' -> org.springframework.validation.BindException: org.springframework.validation.BeanPropertyBindingResult: 0 errors], status = Active]; exposed session output is map[[empty]] 2012-01-23 13:24:01,299 DEBUG [org.springframework.webflow.engine.impl.FlowExecutionImpl] - [Ended] - this execution is now inactive 2012-01-23 13:24:01,299 DEBUG [org.springframework.webflow.engine.Transition] - Completed execution of [Transition@3a97263f on = [eventId = 'success'], to = redirect], as a result the flow execution has ended 2012-01-23 13:24:01,299 DEBUG [org.springframework.webflow.engine.Transition] - Completed execution of [Transition@153e5454 on = *, to = PasswordWarningCheck], as a result the flow execution has ended 2012-01-23 13:24:01,299 DEBUG [org.springframework.webflow.engine.Transition] - Completed execution of [Transition@1ccdf3c2 on = [eventId = 'success'], to = warn], as a result the flow execution has ended 2012-01-23 13:24:01,299 DEBUG [org.springframework.webflow.engine.Transition] - Completed execution of [Transition@22a79c31 on = flowScope.service != null, to = generateServiceTicket], as a result the flow execution has ended 2012-01-23 13:24:01,299 DEBUG [org.springframework.webflow.engine.Transition] - Completed execution of [Transition@7228c7a1 on = [eventId = 'success'], to = serviceCheck], as a result the flow execution has ended 2012-01-23 13:24:01,300 DEBUG [org.springframework.webflow.engine.Transition] - Completed execution of [Transition@4aad8dbc on = [eventId = 'success'], to = sendTicketGrantingTicket], as a result the flow execution has ended 2012-01-23 13:24:01,300 DEBUG [org.springframework.webflow.engine.Transition] - Completed execution of [Transition@653cca0e on = [eventId = 'success'], to = submit], as a result the flow execution has ended 2012-01-23 13:24:01,300 DEBUG [org.springframework.webflow.engine.Transition] - Completed execution of [Transition@30a14e84 on = [eventId = 'submit'], to = bindAndValidate], as a result the flow execution has ended 2012-01-23 13:24:01,300 DEBUG [org.springframework.webflow.execution.repository.continuation.ContinuationFlowExecutionRepository] - Removing flow execution with key '_cE24887C6-9565-C375-A8C5-33FA66473A73_k624F3F4A-1285-A74C-817E-BCD7C80D0D7D' from repository 2012-01-23 13:24:01,300 DEBUG [org.springframework.webflow.conversation.impl.SessionBindingConversationManager] - Getting conversation E24887C6-9565-C375-A8C5-33FA66473A73 2012-01-23 13:24:01,300 DEBUG [org.springframework.webflow.conversation.impl.SessionBindingConversationManager] - Ending conversation E24887C6-9565-C375-A8C5-33FA66473A73 2012-01-23 13:24:01,300 DEBUG [org.springframework.webflow.conversation.impl.SessionBindingConversationManager] - Unlocking conversation E24887C6-9565-C375-A8C5-33FA66473A73 2012-01-23 13:24:01,300 DEBUG [org.springframework.webflow.executor.support.FlowRequestHandler] - Returning [resume] [ResponseInstruction@76938855 flowExecutionKey = [null], viewSelection = externalRedirect:'https://webtest.its.unb.ca/cas-dev/index.cgi?ticket=ST-2-aeTTN5A7qDb7oAcqilHJ-cas', flowExecutionContext = [Inactive execution of 'login-webflow']] 2012-01-23 13:24:01,301 DEBUG [org.springframework.web.servlet.DispatcherServlet] - Rendering view [org.springframework.web.servlet.view.RedirectView: unnamed; URL [https://webtest.its.unb.ca/cas-dev/index.cgi?ticket=ST-2-aeTTN5A7qDb7oAcqilHJ-cas]] in DispatcherServlet with name 'cas' 2012-01-23 13:24:01,301 DEBUG [org.springframework.web.servlet.DispatcherServlet] - Successfully completed request ===== /cas/samlValidate from mod_auth_cas ==> /var/log/httpd/ssl_access_log <== 131.202.6.40 - - [23/Jan/2012:13:24:01 -0400] "POST /cas/samlValidate?TARGET=https%3a%2f%2fwebtest.its.unb.ca%2fcas-dev%2findex.cgi HTTP/1.1" 200 1480 "-" "mod_auth_cas 1.0.9.1" ==> /var/log/tomcat6/cas.log <== 2012-01-23 13:24:01,310 DEBUG [org.springframework.jdbc.datasource.DataSourceTransactionManager] - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_READ_COMMITTED,timeout_5 2012-01-23 13:24:01,310 DEBUG [org.springframework.jdbc.datasource.DataSourceTransactionManager] - Acquired Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@40ca6f53] for JDBC transaction 2012-01-23 13:24:01,310 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils] - Changing isolation level of JDBC Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@40ca6f53] to 2 2012-01-23 13:24:01,312 DEBUG [org.springframework.jdbc.datasource.DataSourceTransactionManager] - Switching JDBC Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@40ca6f53] to manual commit 2012-01-23 13:24:01,312 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - Executing prepared SQL update 2012-01-23 13:24:01,312 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - Executing prepared SQL statement [Update COM_STATISTICS Set STAT_COUNT = STAT_COUNT + 1 WHERE STAT_SERVER_IP = ? AND STAT_DATE = ? AND APPLIC_CD = ? AND STAT_PRECISION = ? AND STAT_NAME = ?] 2012-01-23 13:24:01,314 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - SQL update affected 1 rows 2012-01-23 13:24:01,314 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - Executing prepared SQL update 2012-01-23 13:24:01,314 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - Executing prepared SQL statement [Update COM_STATISTICS Set STAT_COUNT = STAT_COUNT + 1 WHERE STAT_SERVER_IP = ? AND STAT_DATE = ? AND APPLIC_CD = ? AND STAT_PRECISION = ? AND STAT_NAME = ?] 2012-01-23 13:24:01,315 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - SQL update affected 0 rows 2012-01-23 13:24:01,316 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - Executing prepared SQL update 2012-01-23 13:24:01,316 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - Executing prepared SQL statement [Insert into COM_STATISTICS(STAT_SERVER_IP, STAT_DATE, APPLIC_CD, STAT_PRECISION, STAT_COUNT, STAT_NAME) VALUES(?, ?, ?, ?, 1, ?)] 2012-01-23 13:24:01,316 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - SQL update affected 1 rows 2012-01-23 13:24:01,317 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - Executing prepared SQL update 2012-01-23 13:24:01,317 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - Executing prepared SQL statement [Update COM_STATISTICS Set STAT_COUNT = STAT_COUNT + 1 WHERE STAT_SERVER_IP = ? AND STAT_DATE = ? AND APPLIC_CD = ? AND STAT_PRECISION = ? AND STAT_NAME = ?] 2012-01-23 13:24:01,318 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - SQL update affected 0 rows 2012-01-23 13:24:01,318 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - Executing prepared SQL update 2012-01-23 13:24:01,318 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - Executing prepared SQL statement [Insert into COM_STATISTICS(STAT_SERVER_IP, STAT_DATE, APPLIC_CD, STAT_PRECISION, STAT_COUNT, STAT_NAME) VALUES(?, ?, ?, ?, 1, ?)] 2012-01-23 13:24:01,319 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - SQL update affected 1 rows 2012-01-23 13:24:01,320 DEBUG [org.springframework.jdbc.datasource.DataSourceTransactionManager] - Initiating transaction commit 2012-01-23 13:24:01,320 DEBUG [org.springframework.jdbc.datasource.DataSourceTransactionManager] - Committing JDBC transaction on Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@40ca6f53] 2012-01-23 13:24:01,321 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils] - Resetting isolation level of JDBC Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@40ca6f53] to 4 2012-01-23 13:24:01,321 DEBUG [org.springframework.jdbc.datasource.DataSourceTransactionManager] - Releasing JDBC Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@40ca6f53] after transaction 2012-01-23 13:24:01,321 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils] - Returning JDBC Connection to DataSource 2012-01-23 13:24:01,391 DEBUG [org.springframework.web.servlet.DispatcherServlet] - DispatcherServlet with name 'cas' processing request for [/cas/samlValidate] 2012-01-23 13:24:01,392 DEBUG [org.springframework.web.servlet.handler.SimpleUrlHandlerMapping] - Mapping [/samlValidate] to handler 'org.jasig.cas.web.ServiceValidateController@25b8737f' 2012-01-23 13:24:01,392 DEBUG [org.jasig.cas.web.support.SamlArgumentExtractor] - Extractor generated service for: https://webtest.its.unb.ca/cas-dev/index.cgi 2012-01-23 13:24:01,392 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - Creating new transaction with name [org.jasig.cas.CentralAuthenticationService.validateServiceTicket]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT 2012-01-23 13:24:01,392 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@2dc9b4e7] for JPA transaction 2012-01-23 13:24:01,393 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - Exposing JPA transaction as JDBC transaction [SimpleConnectionHandle: com.mchange.v2.c3p0.impl.NewProxyConnection@7cff7c63] 2012-01-23 13:24:01,393 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - Attempting to retrieve ticket [ST-2-aeTTN5A7qDb7oAcqilHJ-cas] 2012-01-23 13:24:01,393 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - Ticket [ST-2-aeTTN5A7qDb7oAcqilHJ-cas] found in registry. 2012-01-23 13:24:01,393 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - Removing ticket [ST-2-aeTTN5A7qDb7oAcqilHJ-cas] from registry 2012-01-23 13:24:01,393 DEBUG [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - Attempting to retrieve ticket [ST-2-aeTTN5A7qDb7oAcqilHJ-cas] 2012-01-23 13:24:01,394 DEBUG [org.springframework.jdbc.datasource.DataSourceTransactionManager] - Creating new transaction with name [null]: PROPAGATION_REQUIRED,ISOLATION_READ_COMMITTED,timeout_5 2012-01-23 13:24:01,394 DEBUG [org.springframework.jdbc.datasource.DataSourceTransactionManager] - Acquired Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@49e5ab72] for JDBC transaction 2012-01-23 13:24:01,394 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils] - Changing isolation level of JDBC Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@49e5ab72] to 2 2012-01-23 13:24:01,394 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - Initiating transaction commit 2012-01-23 13:24:01,394 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl@2dc9b4e7] 2012-01-23 13:24:01,395 DEBUG [org.springframework.jdbc.datasource.DataSourceTransactionManager] - Switching JDBC Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@49e5ab72] to manual commit 2012-01-23 13:24:01,395 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - Executing prepared SQL update 2012-01-23 13:24:01,395 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - Executing prepared SQL statement [Update COM_STATISTICS Set STAT_COUNT = STAT_COUNT + 1 WHERE STAT_SERVER_IP = ? AND STAT_DATE = ? AND APPLIC_CD = ? AND STAT_PRECISION = ? AND STAT_NAME = ?] 2012-01-23 13:24:01,396 DEBUG [org.springframework.orm.jpa.JpaTransactionManager] - Closing JPA EntityManager [org.hibernate.ejb.EntityManagerImpl@2dc9b4e7] after transaction 2012-01-23 13:24:01,396 DEBUG [org.springframework.orm.jpa.EntityManagerFactoryUtils] - Closing JPA EntityManager 2012-01-23 13:24:01,396 DEBUG [org.springframework.validation.DataBinder] - DataBinder requires binding of required fields [renew] 2012-01-23 13:24:01,396 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - SQL update affected 1 rows 2012-01-23 13:24:01,396 DEBUG [org.springframework.web.servlet.DispatcherServlet] - Rendering view [org.jasig.cas.web.view.Saml10SuccessResponseView: name 'casSamlServiceSuccessView'] in DispatcherServlet with name 'cas' 2012-01-23 13:24:01,397 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - Executing prepared SQL update 2012-01-23 13:24:01,397 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - Executing prepared SQL statement [Update COM_STATISTICS Set STAT_COUNT = STAT_COUNT + 1 WHERE STAT_SERVER_IP = ? AND STAT_DATE = ? AND APPLIC_CD = ? AND STAT_PRECISION = ? AND STAT_NAME = ?] 2012-01-23 13:24:01,398 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - SQL update affected 0 rows 2012-01-23 13:24:01,399 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - Executing prepared SQL update 2012-01-23 13:24:01,399 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - Executing prepared SQL statement [Insert into COM_STATISTICS(STAT_SERVER_IP, STAT_DATE, APPLIC_CD, STAT_PRECISION, STAT_COUNT, STAT_NAME) VALUES(?, ?, ?, ?, 1, ?)] 2012-01-23 13:24:01,399 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - SQL update affected 1 rows 2012-01-23 13:24:01,400 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - Executing prepared SQL update 2012-01-23 13:24:01,400 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - Executing prepared SQL statement [Update COM_STATISTICS Set STAT_COUNT = STAT_COUNT + 1 WHERE STAT_SERVER_IP = ? AND STAT_DATE = ? AND APPLIC_CD = ? AND STAT_PRECISION = ? AND STAT_NAME = ?] 2012-01-23 13:24:01,401 DEBUG [org.springframework.web.servlet.DispatcherServlet] - Successfully completed request 2012-01-23 13:24:01,401 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - SQL update affected 0 rows 2012-01-23 13:24:01,402 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - Executing prepared SQL update 2012-01-23 13:24:01,402 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - Executing prepared SQL statement [Insert into COM_STATISTICS(STAT_SERVER_IP, STAT_DATE, APPLIC_CD, STAT_PRECISION, STAT_COUNT, STAT_NAME) VALUES(?, ?, ?, ?, 1, ?)] 2012-01-23 13:24:01,403 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - SQL update affected 1 rows 2012-01-23 13:24:01,403 DEBUG [org.springframework.jdbc.datasource.DataSourceTransactionManager] - Initiating transaction commit 2012-01-23 13:24:01,403 DEBUG [org.springframework.jdbc.datasource.DataSourceTransactionManager] - Committing JDBC transaction on Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@49e5ab72] 2012-01-23 13:24:01,404 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils] - Resetting isolation level of JDBC Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@49e5ab72] to 4 2012-01-23 13:24:01,404 DEBUG [org.springframework.jdbc.datasource.DataSourceTransactionManager] - Releasing JDBC Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@49e5ab72] after transaction 2012-01-23 13:24:01,404 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils] - Returning JDBC Connection to DataSource 2012-01-23 13:24:45,243 DEBUG [org.quartz.core.JobRunShell] - Calling execute on job DEFAULT.serviceRegistryReloaderJobDetail 2012-01-23 13:24:45,243 INFO [org.jasig.cas.services.DefaultServicesManagerImpl] - Reloading registered services. 2012-01-23 13:24:45,243 DEBUG [org.springframework.orm.jpa.JpaTemplate] - Creating new EntityManager for JpaTemplate execution On 2012-01-23, at 10:42, Marvin Addison wrote: >> I have org.jasig, org.quartz and org.springframework turned up to DEBUG and >> I don't see anything about attributes in the logs after restarting Tomcat. A >> grep for "eduPerson" or "attribute" turns up nothing that indicates to me >> they're even being fetched. > > Post some logs anyway so we can see the authentication flow. > Hopefully something will jump out. > > M > > -- > You are currently subscribed to [email protected] as: > [email protected] > To unsubscribe, change settings or access archives, see > http://www.ja-sig.org/wiki/display/JSG/cas-user > -- Joel Goguen Developer Enterprise Solutions Information Technology Services University of New Brunswick E-mail: [email protected] Phone: (506) 453-4872 Fax: (506) 453-3590 -- You are currently subscribed to [email protected] as: [email protected] To unsubscribe, change settings or access archives, see http://www.ja-sig.org/wiki/display/JSG/cas-user
