A few updates: I managed to reproduce the original issue this week using
the MergingAttributeDao method. This time I have it reproduced in a testing
environment. With org.jasig.cas as debug, nothing jumps out, it just
suddenly errors out (stacktrace attached at the end).
I took some time today to clean up some of our custom authenticators, and
cleaned up my configuration to be more like the given sample in the 4.2.X
branch to see if any of the discrepancies there would cause something like
this.
Some changes include:
- Removing call to 'new SimplePrincipalFactory()' in extensions
of AbstractUsernamePasswordAuthenticationHandlers, and using the
principalFactory provided. Doubtful that this will affect anything, as all
PrincipalFactories seem to be "simple", and I am also having this issue on
built in LDAP handlers as well.
- Removing the proxyAuthenticationHandler from the context config. I am not
using a proxy configuration - the less variance, the better.
- Refactor all resolvers to be the same. Merge all the
attributeRepositories into a single repository. Before I had separate
static repository maps via the NamedStubPersonAttributeDao that would
append an attribute depending on how it authenticated. I've moved the logic
for that to the jdbc attribute dao retrieval. I am no longer depending on the
NamedStubPersonAttributeDao, and only merging 2 jdbc + ldap repositories
under a single resolver.
None of these changes strike me as something that would fix something like
the issue I was seeing before. Even so, I'm able to log in on my local
instance ~75k times with no issue. I'm going to deploy to a servlet
container and run another batch of tests there. I'll let you know how
things pan out.
-Jeff
----
2016-11-22 20:41:57,556 DEBUG
[org.jasig.services.persondir.support.MergingPersonAttributeDaoImpl] -
Retrieved
attributes='[NamedPersonImpl[name=jwong,attributes={Email=[email@company],
FirstName=[Jeff], LastName=[Wong], username=[jwong]}]]' for
query='{username=[jwong]}', isFirstQuery=false,
currentlyConsidering='org.jasig.services.persondir.support.jdbc.SingleRowJdbcPersonAttributeDao@1
e5e658',
resultAttributes='[AttributeNamedPersonImpl[name=jwong,attributes={userType=[internal],
username=[jwong]}]]'
2016-11-22 20:41:57,569 DEBUG
[org.jasig.cas.web.flow.AuthenticationViaFormAction] - 'principal' cannot
be null. Check the correctness of @Audit annotation at the following audit
point: execution(public abstract
org.jasig.cas.authentication.Authentication
org.jasig.cas.authentication.AuthenticationManager.authenticate(org.jasig.cas.authentication.AuthenticationTransaction))
java.lang.IllegalArgumentException: 'principal' cannot be null.
Check the correctness of @Audit annotation at the following audit point:
execution(public abstract org.jasig.cas.authentication.Authentication
org.jasig.cas.authentication.AuthenticationManager.authenticate(org.jasig.cas.authentication.AuthenticationTransaction))
at
org.jasig.inspektr.audit.AuditActionContext.assertNotNull(AuditActionContext.java:80)
at
org.jasig.inspektr.audit.AuditActionContext.<init>(AuditActionContext.java:62)
at
org.jasig.inspektr.audit.AuditTrailManagementAspect.executeAuditCode(AuditTrailManagementAspect.java:153)
at
org.jasig.inspektr.audit.AuditTrailManagementAspect.handleAuditTrail(AuditTrailManagementAspect.java:141)
at sun.reflect.GeneratedMethodAccessor511.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:620)
at
org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:609)
at
org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:68)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:168)
at
org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at
com.ryantenney.metrics.spring.MeteredMethodInterceptor.invoke(MeteredMethodInterceptor.java:45)
at
com.ryantenney.metrics.spring.MeteredMethodInterceptor.invoke(MeteredMethodInterceptor.java:32)
at
com.ryantenney.metrics.spring.AbstractMetricMethodInterceptor.invoke(AbstractMetricMethodInterceptor.java:59)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at
com.ryantenney.metrics.spring.TimedMethodInterceptor.invoke(TimedMethodInterceptor.java:48)
at
com.ryantenney.metrics.spring.TimedMethodInterceptor.invoke(TimedMethodInterceptor.java:34)
at
com.ryantenney.metrics.spring.AbstractMetricMethodInterceptor.invoke(AbstractMetricMethodInterceptor.java:59)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at
com.ryantenney.metrics.spring.CountedMethodInterceptor.invoke(CountedMethodInterceptor.java:46)
at
com.ryantenney.metrics.spring.CountedMethodInterceptor.invoke(CountedMethodInterceptor.java:32)
at
com.ryantenney.metrics.spring.AbstractMetricMethodInterceptor.invoke(AbstractMetricMethodInterceptor.java:59)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:208)
at com.sun.proxy.$Proxy763.authenticate(Unknown Source)
at
org.jasig.cas.authentication.DefaultAuthenticationTransactionManager.handle(DefaultAuthenticationTransactionManager.java:29)
at
org.jasig.cas.web.flow.AuthenticationViaFormAction.createTicketGrantingTicket(AuthenticationViaFormAction.java:165)
at
org.jasig.cas.web.flow.AuthenticationViaFormAction.submit(AuthenticationViaFormAction.java:92)
at sun.reflect.GeneratedMethodAccessor526.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
On Tuesday, July 19, 2016 at 3:09:59 PM UTC-7, Jeffrey Wong wrote:
>
> After about a month of working perfectly on 4.2.2 deployed to tomcat7,
> running under java8, randomly the in-memory ticketing system would not
> create any more tickets. Restarting the tomcat instance fixed it, but I'm
> wondering why CAS would randomly break on me after working so well! Using a
> LDAP (AD) backed user base with a mysql backed attribute DB. We have pretty
> minimal traffic, so I'm not sure why I am seeing issues after such a small
> amount of time.
>
> Despite having an <AsyncRoot level="error">, no errors have been thrown at
> the time of issue.
>
> Unfortunately, I've only had the org.springframework.jdbc logger set to
> debug, and all others at info, so I have very minimal logging around the
> issue.
>
> I'm noticing both the ldap auth AND the jdbc handlers returning without
> issues (no errors). ...But no tickets?
>
> Here's a sample of the logs:
>
> 2016-07-19 16:28:16,399 INFO
> [org.jasig.cas.authentication.PolicyBasedAuthenticationManager] -
> <LdapAuthenticationHandler successfully authenticated user1>
> 2016-07-19 16:28:16,400 DEBUG [org.springframework.jdbc.core.JdbcTemplate] -
> <Executing prepared SQL query>
> 2016-07-19 16:28:16,400 DEBUG [org.springframework.jdbc.core.JdbcTemplate] -
> <Executing prepared SQL statement[SELECT
> ID,username,FirstName,LastName,Email FROM User WHERE UserName = ?]>
> 2016-07-19 16:28:16,400 DEBUG
> [org.springframework.jdbc.datasource.DataSourceUtils] - <Fetching JDBC
> Connection from DataSource>
> 2016-07-19 16:28:16,401 DEBUG
> [org.springframework.jdbc.datasource.DataSourceUtils] - <Returning JDBC
> Connection to DataSource>
> 2016-07-19 16:28:19,015 INFO
> [org.jasig.cas.authentication.PolicyBasedAuthenticationManager] -
> <LdapAuthenticationHandler successfully authenticated user2>
> 2016-07-19 16:28:19,015 DEBUG [org.springframework.jdbc.core.JdbcTemplate] -
> <Executing prepared SQL query>
> 2016-07-19 16:28:19,015 DEBUG [org.springframework.jdbc.core.JdbcTemplate] -
> <Executing prepared SQL statement[SELECT
> ID,username,FirstName,LastName,Email FROM User WHERE UserName = ?]>
> 2016-07-19 16:28:19,015 DEBUG
> [org.springframework.jdbc.datasource.DataSourceUtils] - <Fetching JDBC
> Connection from DataSource>
> 2016-07-19 16:28:19,017 DEBUG
> [org.springframework.jdbc.datasource.DataSourceUtils] - <Returning JDBC
> Connection to DataSource>
>
> Immediately before this, I've seen tickets that are created (an audit log
> is posted that a ticket granting ticket has been created and validated, and
> all is good). There are no exceptions thrown between when the tickets were
> able to be created and when there was this bottleneck.
>
> On the front end, after the logs say 'success' without a ticket created,
> they are redirected to the main cas login page. Reproducing this is also
> difficult as it will stop intermittently, without warning.
>
> What are the best ways to debug or resolve these sorts of issues? What
> could be causing this issue?
>
> Thanks in advance,
> Jeff
>
--
- CAS gitter chatroom: https://gitter.im/apereo/cas
- CAS mailing list guidelines: https://apereo.github.io/cas/Mailing-Lists.html
- CAS documentation website: https://apereo.github.io/cas
- CAS project website: https://github.com/apereo/cas
---
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 [email protected].
To view this discussion on the web visit
https://groups.google.com/a/apereo.org/d/msgid/cas-user/b8677844-77e3-4856-9be4-193c0ced4f60%40apereo.org.
