After a month, no tickets created in 4.2.2?
54 views
Skip to first unread message
Jeffrey Wong
Jul 19, 2016, 6:06:18 PM7/19/16
to jasig-cas-user
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>
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
Jeffrey Wong
Jul 19, 2016, 6:10:00 PM7/19/16
to CAS Community
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/23b96c4d-0997-4da1-9051-7ddf1560e8bb%40apereo.org.
For more options, visit https://groups.google.com/a/apereo.org/d/optout.
Misagh Moayyed
Jul 20, 2016, 5:31:35 AM7/20/16
to CAS Community
Does your log show that tickets are cleaned up successfully? Is your expiration policy set up to allow the cleaner to expire and clean tickets successfully?
Without logs, it’s just a guessing game. My bet is, somehow you’ve run out of memory.
--
Misagh
Misagh
Jeffrey Wong
Jul 20, 2016, 6:27:10 PM7/20/16
to CAS Community, mmoa...@unicon.net
Grepping through what I have, I can confirm that the tickets are being removed, as I do have log statements like the following:
catalina.out.2.gz:2016-07-08 22:19:31,948 INFO [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <1 expired tickets found and removed.>
catalina.out.2.gz:2016-07-08 22:21:32,004 INFO [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <2 expired tickets found and removed.>
I'm using the default in memory registry, the default tgt.maxTimeToLiveInSeconds + tgt.timeToKillInSeconds. st.timeToKillInSeconds=60.
Other pretty bare bones defaults:
<alias name="serviceThemeResolver" alias="themeResolver" />
<alias name="jsonServiceRegistryDao" alias="serviceRegistryDao" />
<alias name="defaultTicketRegistry" alias="ticketRegistry" />
<alias name="ticketGrantingTicketExpirationPolicy" alias="grantingTicketExpirationPolicy" />
<alias name="multiTimeUseOrTimeoutExpirationPolicy" alias="serviceTicketExpirationPolicy" />
<alias name="anyAuthenticationPolicy" alias="authenticationPolicy" />
<alias name="acceptAnyAuthenticationPolicyFactory" alias="authenticationPolicyFactory" />
Would you recommend perhaps a different ticket registry at this point perhaps? I don't think I'm hitting the maximum amount of tickets that the default ticket registry can hold by any means, since the maximum amount of tickets I'm seeing expire is 20. Mostly it's between 0-2 tickets that are expired, so I very much doubt the tickets being the memory bottleneck.
---
Before I posted the above, I dug a little and noticed a strange ~200 tickets being cleaned up a bit before the issue (an uptick in cleanup tickets). Perhaps moving to a more robust ticket registry (not just in memory) might actually help to mitigate then.
Are service tickets also being cleaned up with the same default ticket registry? What tickets should show up in that 'expired' count? TGT only, or TGT + STs?
For testing, I logged in to a test instance where the tgt expirey was set to 10 seconds. 10 times: 15 expired tickets. I logged in 20 times. 29 expired tickets.
What other items are included in the expired count?
Misagh Moayyed
Jul 22, 2016, 2:24:10 AM7/22/16
to CAS Community
All expired tickets are removed by the cleaner, regardless of type. Come to think of it, do you use CAS for its proxy authentication features? That *might* have something to do with it, if you do.
I personally don’t know if I’d recommend switching, because I don’t know what the problem is. Generally, switching to something more robust and distributed is a good idea, but if the problem is something else, it will simply repeat and your new registry will have done nothing to fix it. I would instead turn up logs, load test as much as possible and keep it running under test for some time. Observe.
--
Misagh
Misagh
Jeffrey Wong
Aug 22, 2016, 6:49:55 PM8/22/16
to CAS Community, mmoa...@unicon.net
I am not making use of proxy granting tickets, but I'll report back if it's still an issue once 2.2.5 drops.
In the version that I have currently deployed, the counts on the tickets themselves seem strange to me - When I log in 10 times, that's 10 TGTs and 10 STs, correct? So I should expect 20 tickets to be cleaned up, rather than 15. If it's only counting TGTs, then I should have 10 tickets total.
I've turned on debugging, and will be monitoring this issue for when it happens again, and let you know what I see in the logs. Meanwhile, can you confirm or correct my understanding of the current ticket cleanup log? It looks pretty strange from my end.
Misagh Moayyed
Aug 23, 2016, 1:13:37 AM8/23/16
to CAS Community
I hate to say this, but it depends! It depends what you mean by login, and it depends what you mean by 10 :)
Before we start to discuss the answer to the ultimate question of life, the universe, and everything let me explode this a bit.
When you log into CAS, you get a TGT. You get an SSO session. That TGT remains alive so long you don’t log out and so long its expiration policy says it should live. For every application you log into, you will get an ST. The application ideally keeps track of the user session so it wouldn’t have to ask for more STs every time you refresh its page for instance. So:
If you log in 10 times to 10 different apps, you get 1 TGT and 10 STs. If the act of logging in requires you to present credentials every time, (i.e. renew=true) then that’s still in the end 1 TGTs and 10 STs active and legible for clean up, because every time you generate a new TGT, the old one is immediately killed and destroyed and it will not show up in the clean up log.
The cleanup process cleans expired tickets. Regardless of the ticket type. Doesn’t matter of it’s a TGT, ST, OC, etc. There are many many other types. All you have to remember is, if it’s expired, it gets removed at certain intervals. The only exception to this rule is, proxy-tickets are not removed by the clean up process when you “logout” forcefully, and this something that is fixed in the next patch release, thanks to William. But you’re not using PTs, so...
--
Misagh
Misagh
Date: August 22, 2016 at 3:50:03 PM
To: CAS Community <cas-...@apereo.org>
Cc: mmoa...@unicon.net <mmoa...@unicon.net>
To: CAS Community <cas-...@apereo.org>
Cc: mmoa...@unicon.net <mmoa...@unicon.net>
Jeffrey Wong
Aug 23, 2016, 5:04:53 PM8/23/16
to CAS Community, mmoa...@unicon.net
Ah, looks to be that the PT fix won't affect my issues then - Let me clarify how I'm doing my testing in that case:
I'm creating a new session (new cookie map) with every login, over the same user. I'm scraping the lt, execution, and _eventId off of the initial payload, and making a post request with those parameters with username+password.
In the logs, each login creates a new TGT (since I'm not sharing cookies per request, I'll have a unique TGT per login) and a new ST. I've turned on debugs and can confirm that with a series of 5 logins, 5 TGT and 5 STs are created. I turned st.timeToKillInSeconds way down (10) to ensure cleanup of all tickets on the next cleaning run. In this test case above, I would expect a total of 10 tickets to be cleaned up on the next cleaner run.
During cleanup, I appear to be missing a count of a ST or two. It occasionally claims between 7 and 9 tickets cleaned. I've counted all 5 TGTs, but the STs appear to only occasionally be cleaned up fully.
To ensure that STs aren't expiring on their own somehow and are strictly expiring as children of TGTs, I have the following settings:
tgt.timeToKillInSeconds=10
st.timeToKillInSeconds=600
It's my understanding that when a TGT gets cleaned, that all STs associated with that TGT are also cleaned up as well, but it doesn't appear that this is the case.
My worry is that there's an orphaned ST in memory somewhere still floating around memory, which would be OK if I were ticketing through ORM, as I could audit active tickets directly in sql, or remove them myself. I think in the meantime, I'll move production ticketing to a (slower, but more easily auditable) ORM solution. I wanted to let you know what I'm seeing on my end in case this is a weird edge case in the cleaner.
Jeffrey Wong
Aug 23, 2016, 5:33:23 PM8/23/16
to CAS Community, mmoa...@unicon.net
Also to note, switching to JPA under the same circumstances, I can confirm that all 10 tickets are consistently reporting in as cleaned (ran over multiple tests). Definitely seems like there's something strange with the in memory ticketing cleaner.
Misagh Moayyed
Aug 23, 2016, 11:54:25 PM8/23/16
to CAS Community
Cool. Thanks for the report. I can run some tests on this, and it would be more reassuring if you were to switch to 4.2.5-SNAPSHOT and test the latest patch that William has put together that handles this sort of thing. If the problem persists, we could further review it before the official 4.2.5, which is in about 10 days.
In 4.2.5, the cleanup logic is shared by all registry types. So the behavior is made consistent across all where the task of ticket removal is then delegated to the individual registry that knows how to talk to the source. I suggest that you run your same batch of tests against that baseline, and if you still see the issue, please post back.
--
Misagh
Misagh
Date: August 23, 2016 at 2:33:34 PM
To: CAS Community <cas-...@apereo.org>
Cc: mmoa...@unicon.net <mmoa...@unicon.net>
To: CAS Community <cas-...@apereo.org>
Cc: mmoa...@unicon.net <mmoa...@unicon.net>
Jeffrey Wong
Aug 24, 2016, 5:20:27 PM8/24/16
to CAS Community, mmoa...@unicon.net
I'm still getting inconsistent ST cleanup summaries using 4.2.5-SNAPSHOT with the default in memory cleaner - See the attached log.
Note that all service tickets are found for cleanup, but only two here have logged "Attempting to retrieve ticket". It appears in this version that all service tickets are found, but only are two are 'expired' at the point where the TGTs expire.
Again, this is despite having st.timeToKillInSeconds=600. The default registry does 2 minutes pass per clean - the STs should all be expiring when the TGTs expire (if I'm understanding correctly) - otherwise, they should expire when timeToKillInSeconds passes. In this case 10 minutes.
Assuming the STs expire on their own, I waited 10 minutes:
grep "expired tickets found and removed." cas.log:
2016-08-24 16:47:21,814 INFO [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - 7 expired tickets found and removed. <- 5 TGTs + 2 STs, the last line of the attached log
2016-08-24 16:49:21,714 INFO [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - 0 expired tickets found and removed.
2016-08-24 16:51:21,718 INFO [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - 0 expired tickets found and removed.
2016-08-24 16:53:21,723 INFO [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - 0 expired tickets found and removed.
2016-08-24 16:55:21,715 INFO [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - 0 expired tickets found and removed.
2016-08-24 16:57:21,712 INFO [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - 0 expired tickets found and removed.
2016-08-24 16:59:21,715 INFO [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - 0 expired tickets found and removed.
2016-08-24 17:01:21,717 INFO [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - 0 expired tickets found and removed.
2016-08-24 17:03:21,711 INFO [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - 0 expired tickets found and removed.
2016-08-24 17:05:21,711 INFO [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - 0 expired tickets found and removed.
2016-08-24 17:07:21,711 INFO [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - 0 expired tickets found and removed.
2016-08-24 17:09:21,711 INFO [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - 0 expired tickets found and removed.
2016-08-24 17:11:21,713 INFO [org.jasig.cas.ticket.registry.DefaultTicketRegistry] - 0 expired tickets found and removed.
The 3 floating STs should have expired somewhere, but don't appear to be.
Misagh Moayyed
Aug 25, 2016, 1:34:10 AM8/25/16
to CAS Community
You’re right. There seems to be a problem, but it’s not a cleanup problem. Your logs actually show all 10 tickets are being removed correctly. If you scan through, you’ll find “Removing ticket [TGT-…]” 5 times and you’ll find "Removed ticket [ST-…” 5 times.
The count is inconsistent; because orphaned STs are counted and deleted separately. STs that are attached to a TGT are not counted, yet are cleaned when the TGT is removed. So in effect, you have 5 TGTs removed, 2 orphaned STs (counting up to 7 in the final output) and other STs are removed as part of those TGTs which you see the removal in the logs but not in the final count of them.
Do file a bug please.
Back to the original issue; the cleanup process seems all correct. The issue lies somewhere else.
--
Misagh
Misagh
Date: August 24, 2016 at 2:20:36 PM
To: CAS Community <cas-...@apereo.org>
Cc: mmoa...@unicon.net <mmoa...@unicon.net>
To: CAS Community <cas-...@apereo.org>
Cc: mmoa...@unicon.net <mmoa...@unicon.net>
Jeffrey Wong
Aug 25, 2016, 12:43:08 PM8/25/16
to CAS Community, mmoa...@unicon.net
OK, thanks for the confirmation. I sent in a ticket about it.
As for the original issue, I'll continue to monitor to see if I detect anything on my end. Aside from a full debug on the jasig.cas namespace, would there be any other library/namespace that would be beneficial to include in the logs?
Misagh Moayyed
Aug 25, 2016, 1:40:14 PM8/25/16
to CAS Community
Thanks for the submission.
That should suffice. Watch your server logs as well, and keep an eye up JVM performance and stats.
--
Misagh
Misagh
Date: August 25, 2016 at 9:43:21 AM
To: CAS Community <cas-...@apereo.org>
Cc: mmoa...@unicon.net <mmoa...@unicon.net>
To: CAS Community <cas-...@apereo.org>
Cc: mmoa...@unicon.net <mmoa...@unicon.net>
Jeffrey Wong
Aug 25, 2016, 5:42:35 PM8/25/16
to CAS Community, mmoa...@unicon.net
Ah, JVM stats. Thanks for that tip: I really wasn't looking at my memory closely enough, and I still had a -Xmx128m set (tomcat7 default in ubuntu). I bumped it to 1g (actually this time, confirmed via /status this time) so I'm hoping this helps resolve.
/status wasn't working for localhost by default, but this was due to IPv6 on my end. Would you be open to changing the default cas.securityContext.adminpages.ip=(127\.0\.0\.1|0:0:0:0:0:0:0:1) to support IPv6 localhost?
I'm planning on throwing on a lot more memory monitoring near future. I'm assuming this would be a very likely root cause for these sorts off issues - sorry I didn't catch that earlier.
Hoping this is the ticket (hurr hurr) - I'll let you know if anything else interesting comes up, but I really appreciate your support!
Misagh Moayyed
Aug 26, 2016, 1:56:38 AM8/26/16
to CAS Community
Ah, JVM stats. Thanks for that tip: I really wasn't looking at my memory closely enough, and I still had a -Xmx128m set (tomcat7 default in ubuntu). I bumped it to 1g (actually this time, confirmed via /status this time) so I'm hoping this helps resolve.
Ah! That should do it. I am surprised you were able to last a few months with that setting. My preference is somewhere between 2g and 4g.
/status wasn't working for localhost by default, but this was due to IPv6 on my end. Would you be open to changing the default cas.securityContext.adminpages.ip=(127\.0\.0\.1|0:0:0:0:0:0:0:1) to support IPv6 localhost?
No problem. File an issue please.
I'm planning on throwing on a lot more memory monitoring near future. I'm assuming this would be a very likely root cause for these sorts off issues - sorry I didn't catch that earlier.Hoping this is the ticket (hurr hurr) - I'll let you know if anything else interesting comes up, but I really appreciate your support!
No worries. All I did was to echo back what you already knew.
--
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.57bfda0e.2e81feef.291c%40unicon.net.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/.
Jeffrey Wong
Sep 22, 2016, 2:55:18 PM9/22/16
to CAS Community, mmoa...@unicon.net
Hi again,
It's been about a month and have regularly screened the JVM memory - it looks fine since the memory bumps, running CAS v4.2.4.
However, the server fell over again (using the JPA ticket registry), with the same behavior: upon entering correct credentials, a user is redirected back to the login page rather than logging in. I'm not sure where to go from here to ensure a more reliable service, and would like to hear your input.
While digging, I've found three types of exceptions in the logs:
1: deadlocks
SEVERE: Servlet.service() for servlet [cas] in context with path [/cas] threw exception [Request processing failed; nested exception is org.springframework.webflow.execution.ActionExecutionException: Exception thrown executing org.jasig.cas.web.flow.GenerateServiceTicketAction@4805bd13 in state 'generateServiceTicket' of flow 'login' -- action execution attributes were 'map[[empty]]'] with root cause
com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction [265/9592]
at sun.reflect.GeneratedConstructorAccessor127.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
at com.mysql.jdbc.Util.getInstance(Util.java:387)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:946)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3878)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3814)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2478)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2625)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2551)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1861)
at com.mysql.jdbc.PreparedStatement.executeUpdateInternal(PreparedStatement.java:2073)
at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1751)
at com.mysql.jdbc.PreparedStatement.executeBatchInternal(PreparedStatement.java:1257)
at com.mysql.jdbc.StatementImpl.executeBatch(StatementImpl.java:959)
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeBatch(NewProxyPreparedStatement.java:2544)
2: badly formatted keys
SEVERE: Servlet.service() for servlet [cas] in context with path [/cas] threw exception [Request processing failed; nested exception is org.springframework.webflow.execution.repository.BadlyFormattedFlowExecution
KeyException: Badly formatted flow execution key '', the expected format is '<uuid>_<base64-encoded-flow-state>'] with root cause
org.springframework.webflow.execution.repository.BadlyFormattedFlowExecutionKeyException: Badly formatted flow execution key '', the expected format is '<uuid>_<base64-encoded-flow-state>'
at org.jasig.spring.webflow.plugin.ClientFlowExecutionKey.parse(ClientFlowExecutionKey.java:102)
at org.jasig.spring.webflow.plugin.ClientFlowExecutionRepository.parseFlowExecutionKey(ClientFlowExecutionRepository.java:74)
at org.springframework.webflow.executor.FlowExecutorImpl.resumeExecution(FlowExecutorImpl.java:164)
at org.springframework.webflow.mvc.servlet.FlowHandlerAdapter.handle(FlowHandlerAdapter.java:228)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:959)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:893)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:646)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
at org.apereo.cas.security.ResponseHeadersEnforcementFilter.doFilter(ResponseHeadersEnforcementFilter.java:238)
at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:346)
3: constraint violations
Sep 22, 2016 9:48:20 AM org.apache.catalina.core.StandardWrapperValve invoke
SEVERE: Servlet.service() for servlet [cas] in context with path [/cas] threw exception [Request processing failed; nested exception is org.springframework.webflow.execution.ActionExecutionException: Exception th
rown executing org.jasig.cas.web.flow.GenerateServiceTicketAction@4805bd13 in state 'generateServiceTicket' of flow 'login' -- action execution attributes were 'map[[empty]]'] with root cause
com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException: Cannot add or update a child row: a foreign key constraint fails (`cas`.`SERVICETICKET`, CONSTRAINT `FK(TGTID)` FOREIG
N KEY (`ticketGrantingTicket_ID`) REFERENCES `TICKETGRANTINGTICKET` (`ID`))
at sun.reflect.GeneratedConstructorAccessor131.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:404)
at com.mysql.jdbc.Util.getInstance(Util.java:387)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:932)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3878)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3814)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2478)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2625)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2551)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1861)
at com.mysql.jdbc.PreparedStatement.executeUpdateInternal(PreparedStatement.java:2073)
at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1751)
at com.mysql.jdbc.PreparedStatement.executeBatchInternal(PreparedStatement.java:1257)
at com.mysql.jdbc.StatementImpl.executeBatch(StatementImpl.java:959)
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeBatch(NewProxyPreparedStatement.java:2544)
at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.performExecution(BatchingBatch.java:110)
at org.hibernate.engine.jdbc.batch.internal.BatchingBatch.doExecuteBatch(BatchingBatch.java:97)
at org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.execute(AbstractBatchImpl.java:147)
at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.executeBatch(JdbcCoordinatorImpl.java:214)
at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:470)
I'm hoping something is just mis-configured in my config, and wondering if the exceptions here give any clue as to what they might be. Exceptions 1 and 3 seem like something is strange with my JPA registry. I'm using C3P0 as my jdbc connection pool ('com.mchange:c3p0:0.9.5.2'), and mysql-connector ('mysql:mysql-connector-java:5.1.38').
Thanks,
Jeff
Jeffrey Wong
Sep 23, 2016, 6:45:51 PM9/23/16
to CAS Community, mmoa...@unicon.net
On suggestions from another user with similar issues using JPA, I have changed and deployed CAS using a hazelcast ticketing database.
I'll let you know if I have any success with this configuration.
Jeffrey Wong
Nov 1, 2016, 9:24:26 PM11/1/16
to CAS Community, mmoa...@unicon.net
This issue occurred again tonight. Nothing of note in the logs again, with plenty of jvm memory + disk space left. It just will start redirecting users to the login page as if a failed login occurred, but without displaying any error messages.
Typing in an incorrect password is caught and the error is displayed as expected with an authentication failed audit. Typing in a correct password will log a successful authentication, but not generate/validate any service tickets in the audit.
This is not related to any LDAP connectivity (this was my reason for updating in the first place) as I also tested on local password storage during this outage as well. Swapping ticketing systems does not seem to have helped.
Any suggestions of what else I should try? Would getting out of tomcat and running it under a separate container help?
- 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 cas-user+u...@apereo.org.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/52a1362d-e821-476a-a10d-83d317d79ecd%40apereo.org.To unsubscribe from this group and stop receiving emails from it, send an email to cas-user+u...@apereo.org.
dkopy...@unicon.net
Nov 2, 2016, 6:34:52 AM11/2/16
to CAS Community, Jeffrey Wong, mmoa...@unicon.net
4.2.2, right? One other suggestion would be to get on the latest release in the 4.2.x series, that is 4.2.6 ... or even get on the v5 bandwagon
Cheers,
D.
Jeffrey Wong
Nov 2, 2016, 12:27:52 PM11/2/16
to CAS Community, awo...@gmail.com, mmoa...@unicon.net, dkopy...@unicon.net
I should clarify, this has been seen in v4.2.5, as that was the latest version of CAS at the time. 4.2.6 doesn't seem to have any commits targeting this issue specifically. I'm definitely gunning for v5 when it drops in GA.
For now, I think I'm going to turn on max debug in production to see if I can get anything.
Jeffrey Wong
Nov 16, 2016, 4:01:26 PM11/16/16
to CAS Community
I just wanted to update - I ran some tests against a separate instance using some automated login scripts with full debug enabled. I was not able to reproduce the exact issue I've seen before. However I did lock myself out of only a single account (as opposed to all users) after ~30k logins. The same behavior is observed: I am redirected back to the original login page with no error message. Typing an invalid password displays an error as normal.
I am currently using JDBC auditing and a hazelcast ticket registry, and have authentication against AD, with JDBC attributes.
Nothing seems out of the ordinary for logging here - After the bug is triggered and observed, further login attemps look like the following. On success, nothing is added to the audit log. On failure, the trial is logged to the jdbc audit log. Even though the LDAP is a success, it appears to hang after that with no query being executed to JDBC:
2016-11-16 12:21:11,331 DEBUG [org.ldaptive.auth.PooledSearchDnResolver] - resolve user=testuser
2016-11-16 12:21:11,332 DEBUG [org.ldaptive.auth.PooledSearchDnResolver] - searching for DN using userFilter
2016-11-16 12:21:11,332 DEBUG [org.ldaptive.SearchOperation] - execute request=[org.ldaptive.SearchRequest@-1425785245::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@309090556::config=[org.ldaptive.ConnectionConfig@1718262659::ldapUrl=ldap://company.domain , connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1612610532::bindDn=CN=testuser,CN=Users,DC=COMPANY, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1965307630::metadata=[ldapUrl=ldap://company.domain , count=1128], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1192906469::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@fa03edb, controlProcessor=org.ldaptive.provider.ControlProcessor@2cc635aa, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@111919cc]
2016-11-16 12:21:11,334 DEBUG [org.ldaptive.SearchOperation] - execute response=[org.ldaptive.Response@671935135::result=[org.ldaptive.SearchResult@-1951941189::entries=[[dn=[], responseControls=null, messageId=-1]], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest@-1425785245::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@309090556::config=[org.ldaptive.ConnectionConfig@1718262659::ldapUrl=ldap://company.domain , connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1612610532::bindDn=CN=testuser,CN=Users,DC=COMPANY, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1965307630::metadata=[ldapUrl=ldap://company.domain , count=1128], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1192906469::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@fa03edb, controlProcessor=org.ldaptive.provider.ControlProcessor@2cc635aa, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@111919cc]
2016-11-16 12:21:11,336 DEBUG [org.ldaptive.SearchOperation] - execute request=[org.ldaptive.SearchRequest@-1201892857::baseDn=CN=Users,DC=COMPANY, searchFilter=[org.ldaptive.SearchFilter@-1616857661::filter=(&(objectCategory=Person)(sAMAccountName={user})), parameters={user=testuser}], returnAttributes=[1.1], searchScope=SUBTREE, timeLimit=0, sizeLimit=0, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@309090556::config=[org.ldaptive.ConnectionConfig@1718262659::ldapUrl=ldap://company.domain , connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1612610532::bindDn=CN=testuser,CN=Users,DC=COMPANY, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1965307630::metadata=[ldapUrl=ldap://company.domain , count=1128], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1192906469::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@fa03edb, controlProcessor=org.ldaptive.provider.ControlProcessor@2cc635aa, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@111919cc]
2016-11-16 12:21:11,343 DEBUG [org.ldaptive.SearchOperation] - execute response=[org.ldaptive.Response@609375658::result=[org.ldaptive.SearchResult@1551860074::entries=[[dn=CN=testuser,CN=Users,DC=COMPANY[], responseControls=null, messageId=-1]], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest@-1201892857::baseDn=CN=Users,DC=COMPANY, searchFilter=[org.ldaptive.SearchFilter@-1616857661::filter=(&(objectCategory=Person)(sAMAccountName={user})), parameters={user=testuser}], returnAttributes=[1.1], searchScope=SUBTREE, timeLimit=0, sizeLimit=0, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@309090556::config=[org.ldaptive.ConnectionConfig@1718262659::ldapUrl=ldap://company.domain , connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1612610532::bindDn=CN=testuser,CN=Users,DC=COMPANY, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1965307630::metadata=[ldapUrl=ldap://company.domain , count=1128], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1192906469::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@fa03edb, controlProcessor=org.ldaptive.provider.ControlProcessor@2cc635aa, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@111919cc]
2016-11-16 12:21:11,343 DEBUG [org.ldaptive.auth.PooledSearchDnResolver] - resolved dn=CN=testuser,CN=Users,DC=COMPANY for user=testuser
2016-11-16 12:21:11,343 DEBUG [org.ldaptive.auth.Authenticator] - authenticate dn=CN=testuser,CN=Users,DC=COMPANY with request=[org.ldaptive.auth.AuthenticationRequest@1666496618::user=testuser, retAttrs=[1.1]]
2016-11-16 12:21:11,343 DEBUG [org.ldaptive.auth.PooledBindAuthenticationHandler] - authenticate criteria=[org.ldaptive.auth.AuthenticationCriteria@751038093::dn=CN=testuser,CN=Users,DC=COMPANY, authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@1666496618::user=testuser, retAttrs=[1.1]]]
2016-11-16 12:21:11,343 DEBUG [org.ldaptive.SearchOperation] - execute request=[org.ldaptive.SearchRequest@-1425785245::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1313467158::config=[org.ldaptive.ConnectionConfig@1956653060::ldapUrl=ldap://company.domain , connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1466625650::bindDn=CN=testuser,CN=Users,DC=COMPANY, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@753503470::metadata=[ldapUrl=ldap://company.domain , count=21], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1707368966::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@fa03edb, controlProcessor=org.ldaptive.provider.ControlProcessor@772891dc, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@5eeec9e8]
2016-11-16 12:21:11,345 DEBUG [org.ldaptive.SearchOperation] - execute response=[org.ldaptive.Response@1585683254::result=[org.ldaptive.SearchResult@-1951941189::entries=[[dn=[], responseControls=null, messageId=-1]], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest@-1425785245::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1313467158::config=[org.ldaptive.ConnectionConfig@1956653060::ldapUrl=ldap://company.domain , connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1466625650::bindDn=CN=testuser,CN=Users,DC=COMPANY, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@753503470::metadata=[ldapUrl=ldap://company.domain , count=21], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1707368966::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@fa03edb, controlProcessor=org.ldaptive.provider.ControlProcessor@772891dc, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@5eeec9e8]
2016-11-16 12:21:11,346 DEBUG [org.ldaptive.BindOperation] - execute request=[org.ldaptive.BindRequest@408092516::bindDn=CN=testuser,CN=Users,DC=COMPANY, saslConfig=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1313467158::config=[org.ldaptive.ConnectionConfig@1956653060::ldapUrl=ldap://company.domain , connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1466625650::bindDn=CN=testuser,CN=Users,DC=COMPANY, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@753503470::metadata=[ldapUrl=ldap://company.domain , count=21], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1707368966::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@fa03edb, controlProcessor=org.ldaptive.provider.ControlProcessor@772891dc, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@5eeec9e8]
2016-11-16 12:21:11,349 DEBUG [org.ldaptive.BindOperation] - execute response=[org.ldaptive.Response@735501669::result=null, resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.BindRequest@408092516::bindDn=CN=testuser,CN=Users,DC=COMPANY, saslConfig=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1313467158::config=[org.ldaptive.ConnectionConfig@1956653060::ldapUrl=ldap://company.domain , connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1466625650::bindDn=CN=testuser,CN=Users,DC=COMPANY, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@753503470::metadata=[ldapUrl=ldap://company.domain , count=21], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1707368966::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@fa03edb, controlProcessor=org.ldaptive.provider.ControlProcessor@772891dc, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@5eeec9e8]
2016-11-16 12:21:11,350 DEBUG [org.ldaptive.auth.PooledBindAuthenticationHandler] - authenticate response=[org.ldaptive.auth.AuthenticationHandlerResponse@272829171::connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1313467158::config=[org.ldaptive.ConnectionConfig@1956653060::ldapUrl=ldap://company.domain , connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1466625650::bindDn=CN=testuser,CN=Users,DC=COMPANY, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@753503470::metadata=[ldapUrl=ldap://company.domain , count=21], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1707368966::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@fa03edb, controlProcessor=org.ldaptive.provider.ControlProcessor@772891dc, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@5eeec9e8], result=true, resultCode=SUCCESS, message=null, controls=null] for criteria=[org.ldaptive.auth.AuthenticationCriteria@751038093::dn=CN=testuser,CN=Users,DC=COMPANY, authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@1666496618::user=testuser, retAttrs=[1.1]]]
2016-11-16 12:21:11,350 DEBUG [org.ldaptive.auth.SearchEntryResolver] - resolve criteria=[org.ldaptive.auth.AuthenticationCriteria@751038093::dn=CN=testuser,CN=Users,DC=COMPANY, authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@1666496618::user=testuser, retAttrs=[1.1]]]
2016-11-16 12:21:11,351 DEBUG [org.ldaptive.SearchOperation] - execute request=[org.ldaptive.SearchRequest@-223087509::baseDn=CN=testuser,CN=Users,DC=COMPANY, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, sizeLimit=0, derefAliases=null, typesOnly=false, binaryAttributes=[objectGUID, objectSid], sortBehavior=UNORDERED, searchEntryHandlers=[org.ldaptive.ad.handler.ObjectGuidHandler@3f939ef7, org.ldaptive.ad.handler.ObjectSidHandler@a7398008], searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1313467158::config=[org.ldaptive.ConnectionConfig@1956653060::ldapUrl=ldap://company.domain , connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1466625650::bindDn=CN=testuser,CN=Users,DC=COMPANY, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@753503470::metadata=[ldapUrl=ldap://company.domain , count=21], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1707368966::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@fa03edb, controlProcessor=org.ldaptive.provider.ControlProcessor@772891dc, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@5eeec9e8]
2016-11-16 12:21:11,352 DEBUG [org.ldaptive.SearchOperation] - execute response=[org.ldaptive.Response@1568478470::result=[org.ldaptive.SearchResult@1551860074::entries=[[dn=CN=testuser,CN=Users,DC=COMPANY[], responseControls=null, messageId=-1]], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest@-223087509::baseDn=CN=testuser,CN=Users,DC=COMPANY, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, sizeLimit=0, derefAliases=null, typesOnly=false, binaryAttributes=[objectGUID, objectSid], sortBehavior=UNORDERED, searchEntryHandlers=[org.ldaptive.ad.handler.ObjectGuidHandler@3f939ef7, org.ldaptive.ad.handler.ObjectSidHandler@a7398008], searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1313467158::config=[org.ldaptive.ConnectionConfig@1956653060::ldapUrl=ldap://company.domain , connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1466625650::bindDn=CN=testuser,CN=Users,DC=COMPANY, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@753503470::metadata=[ldapUrl=ldap://company.domain , count=21], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1707368966::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@fa03edb, controlProcessor=org.ldaptive.provider.ControlProcessor@772891dc, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@5eeec9e8]
2016-11-16 12:21:11,353 DEBUG [org.ldaptive.auth.SearchEntryResolver] - resolved result=[org.ldaptive.SearchResult@1551860074::entries=[[dn=CN=testuser,CN=Users,DC=COMPANY[], responseControls=null, messageId=-1]], references=[]] for criteria=[org.ldaptive.auth.AuthenticationCriteria@751038093::dn=CN=testuser,CN=Users,DC=COMPANY, authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@1666496618::user=testuser, retAttrs=[1.1]]]2016-11-16 12:21:11,353 INFO [org.ldaptive.auth.Authenticator] - Authentication succeeded for dn: CN=testuser,CN=Users,DC=COMPANY
2016-11-16 12:21:11,354 DEBUG [org.ldaptive.auth.Authenticator] - authenticate response=[org.ldaptive.auth.AuthenticationHandlerResponse@272829171::connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1313467158::config=[org.ldaptive.ConnectionConfig@1956653060::ldapUrl=ldap://company.domain , connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1466625650::bindDn=CN=testuser,CN=Users,DC=COMPANY, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@753503470::metadata=[ldapUrl=ldap://company.domain , count=21], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1707368966::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@fa03edb, controlProcessor=org.ldaptive.provider.ControlProcessor@772891dc, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@5eeec9e8], result=true, resultCode=SUCCESS, message=null, controls=null] for dn=CN=testuser,CN=Users,DC=COMPANY with request=[org.ldaptive.auth.AuthenticationRequest@1666496618::user=testuser, retAttrs=[1.1]]
2016-11-16 12:21:11,354 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - Executing prepared SQL query
2016-11-16 12:21:11,354 DEBUG [org.springframework.jdbc.core.JdbcTemplate] - Executing prepared SQL statement [SELECT ID,username,FirstName,LastName,Email,ID_USERTYPE FROM aur_User WHERE UserName = ?]
2016-11-16 12:21:11,354 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils] - Fetching JDBC Connection from DataSource
2016-11-16 12:21:11,355 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils] - Returning JDBC Connection to DataSource
On success (eg, with a different login) after this is logged the following:
2016-11-16 15:55:19,163 DEBUG [org.springframework.jdbc.datasource.DataSourceTransactionManager] - Creating new transaction with name [null]:
PROPAGATION_REQUIRED,ISOLATION_READ_COMMITTED
2016-11-16 15:55:19,163 DEBUG [org.springframework.jdbc.datasource.DataSourceTransactionManager] - Acquired Connection [com.mchange.v2.c3p0.i
mpl.NewProxyConnection@495ef936 [wrapping: com.mysql.jdbc.JDBC4Connection@73765a8a]] for JDBC transaction
2016-11-16 15:55:19,163 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils] - Changing isolation level of JDBC Connection [com.mchang
e.v2.c3p0.impl.NewProxyConnection@495ef936 [wrapping: com.mysql.jdbc.JDBC4Connection@73765a8a]] to 2
Which I do NOT see when the bug occurs.
I'm currently using connection poolings through c3po. However, it's strange to me that this specific test instance only affects a single user.
I'll continue to report what I find, but this seems very strange. Any ideas?
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
---
- 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 cas-user+u...@apereo.org.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/bec03c51-d46e-4f19-86d4-c82294110dfd%40apereo.org.To unsubscribe from this group and stop receiving emails from it, send an email to cas-user+u...@apereo.org.
Jeffrey Wong
Nov 16, 2016, 5:58:21 PM11/16/16
to CAS Community
Spoke too soon - debug wasn't turned on all the way. I found the stacktrace (principal cannot be null), but it appears like it is hidden in debugs - this might want to be a warn level. It sounds like that should be a little more verbose.
The query somehow succeeded the first 30k times, and suddenly the query stopped working. I'll look into seeing if using a different connection pool will help to resolve this.
Here it is not working:
2016-11-16 17:48:19,401 DEBUG [org.jasig.services.persondir.support.jdbc.SingleRowJdbcPersonAttributeDao] - Executed 'SELECT ID,username,FirstName,LastName,Email FROM users WHERE {0}' with arguments [testuser] and got results []
And here is a working example:
Executed 'SELECT ID,username,FirstName,LastName,Email FROM users WHERE {0}' with arguments [jwong] and got results [{ID=2, username=jwong, FirstName=Jeff, LastName=Wong, Email=email}]
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
---
- 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 cas-user+u...@apereo.org.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/c79e4cb9-324f-4103-b744-bd76b60de427%40apereo.org.To unsubscribe from this group and stop receiving emails from it, send an email to cas-user+u...@apereo.org.
Jeffrey Wong
Nov 16, 2016, 7:07:21 PM11/16/16
to CAS Community
However, after restarting, it can login despite the blank results from the JDBC attribute resolver (I'm using cascading attribute resolvers, and assigning static attributes, depending on which method the user resolved against):
Before restart:
2016-11-16 18:03:22,205 DEBUG [org.jasig.services.persondir.support.jdbc.SingleRowJdbcPersonAttributeDao] - Executed 'SELECT ID,username,Firs
tName,LastName,Email FROM users WHERE {0}' with arguments [testuser] and got results []
2016-11-16 18:03:22,210 DEBUG [org.jasig.services.persondir.support.CascadingPersonAttributeDao] - Retrieved attributes='[]' for query='{user
name=[testuser]}', isFirstQuery=false, currentlyConsidering='org.jasig.services.persondir.support.jdbc.SingleRowJdbcPersonAttributeDao@e6c2461'
, resultAttributes='[AttributeNamedPersonImpl[name=testuser,attributes={userType=[internal], username=[testuser]}]]'
2016-11-16 18:03:22,216 DEBUG [org.jasig.services.persondir.support.CascadingPersonAttributeDao] - Aggregated search results '[AttributeNamed
PersonImpl[name=testuser,attributes={userType=[internal], username=[testuser]}]]' for query='{username=[testuser]}'
2016-11-16 18:03:22,217 DEBUG [org.jasig.cas.authentication.principal.PersonDirectoryPrincipalResolver] - Retrieved [2] attribute(s) from the
repository
2016-11-16 18:03:22,230 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.Authenticatio
n 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.Authenticatio
n 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.GeneratedMethodAccessor81.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)
After restart:
2016-11-16 18:04:48,321 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils] - Returning JDBC Connection to DataSource
2016-11-16 18:04:48,323 DEBUG [org.jasig.services.persondir.support.jdbc.SingleRowJdbcPersonAttributeDao] - Executed 'SELECT ID,username,FirstName,LastName,Email FROM users WHERE {0}' with argument
s [testuser] and got results []
2016-11-16 18:04:48,326 DEBUG [org.jasig.services.persondir.support.CascadingPersonAttributeDao] - Retrieved attributes='[]' for query='{username=[testuser]}', isFirstQuery=false, currentlyConsidering='org.jasig.se
rvices.persondir.support.jdbc.SingleRowJdbcPersonAttributeDao@5b528cd', resultAttributes='[AttributeNamedPersonImpl[name=testuser,attributes={userType=[internal], username=[testuser]}]]'
2016-11-16 18:04:48,327 DEBUG [org.jasig.services.persondir.support.CascadingPersonAttributeDao] - Aggregated search results '[AttributeNamedPersonImpl[name=testuser,attributes={userType=[internal], username=[auror
a]}]]' for query='{username=[testuser]}'
2016-11-16 18:04:48,329 DEBUG [org.jasig.cas.authentication.principal.PersonDirectoryPrincipalResolver] - Retrieved [2] attribute(s) from the repository
2016-11-16 18:04:48,330 DEBUG [org.jasig.cas.authentication.PolicyBasedAuthenticationManager] - org.jasig.cas.authentication.principal.PersonDirectoryPrincipalResolver@108b3d3a resolved testuser from testuser
2016-11-16 18:04:48,334 DEBUG [org.jasig.cas.authentication.PolicyBasedAuthenticationManager] - Final principal resolved for this authentication event is testuser
2016-11-16 18:04:48,335 INFO [org.jasig.cas.authentication.PolicyBasedAuthenticationManager] - Authenticated testuser with credentials [testuser].
2016-11-16 18:04:48,336 DEBUG [org.jasig.cas.authentication.PolicyBasedAuthenticationManager] - Attribute map for testuser: {userType=internal, username=testuser}
2016-11-16 18:04:48,337 DEBUG [org.jasig.cas.audit.spi.AssertionAsReturnValuePrincipalResolver] - Trying to see if target's return value is instance of [Assertion]...
2016-11-16 18:04:48,338 DEBUG [org.jasig.cas.audit.spi.AssertionAsReturnValuePrincipalResolver] - Resolving principal from the delegate principal resolver: [org.jasig.cas.audit.spi.TicketOrCredentialPrincipalReso
lver@51e946a9]...
2016-11-16 18:04:48,339 DEBUG [org.jasig.cas.audit.spi.TicketOrCredentialPrincipalResolver] - Resolving argument [AuthenticationTransaction] for audit
2016-11-16 18:04:48,340 DEBUG [org.jasig.cas.audit.spi.TicketOrCredentialPrincipalResolver] - Resolving argument [UsernamePasswordCredential] for audit
2016-11-16 18:04:48,353 DEBUG [org.jasig.cas.authentication.DefaultAuthenticationTransactionManager] - Successful authentication; Collecting authentication result [org.jasig.cas.authentication.ImmutableAuthentica
tion@60e79493]
And it works OK!
I'll see if I can break it again and come up with more detailed logs at the breaking point. I'll keep you updated.
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
---
- 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 cas-user+u...@apereo.org.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/0c321acb-af7a-4ce5-9364-9302a433b235%40apereo.org.To unsubscribe from this group and stop receiving emails from it, send an email to cas-user+u...@apereo.org.
Jeffrey Wong
Nov 18, 2016, 2:01:16 PM11/18/16
to CAS Community
I have a lead on what the issue was related to - I had a setup with the CascadingPersonAttributeDao. Both the original production issue, and the tested behavior was observed under this attribute DAO.
In testing, I have swapped out the AttributeDao with the MergingPersonAttributeDao, using a NoncollidingAttributeAddr merge strategy. I have not observed the same issue I found earlier in my tests since (across ~50k logins). While I still have not been able to re-create the original bug observed, the CascadingPersonAttributeDao seems suspect of a non-deterministic condition. I am unable to re-trigger the bug found during testing in which a single user was locked out under the new merge strategy.
I'm not sure how to reproduce this issue reliably, but I can give some details about my attribute resolution if it helps: I wanted to merge the user query from the DB with a static mapping to keep track of what method they had to login (via ldap, or jdbc, or similar) to determine a user type. I was merging a NamedStubPersonAttributeDao (listed first) with a SingleRowJdbcPersonAttributeDao. The CascadingPersonAttributeDao supported the ReplacingAttributeAdder merge strategy by default (which is what I wanted), so I went with that strategy.
In my own test case, the test user I was using was *not* in the jdbc database for attributes - there were no rows returned from the JDBC query, and so no attributes were added to the static map already defined. Using the CascadingPersonAttributeDao, it will initially be able to discover the principal, and log on. After a number of logins, the principal is unable to be resolved.
Digging into CascadingPersonAttributeDao:
It is <u>highly</u> recommended that the first DAO on the list for this class is the {@link EchoPersonAttributeDaoImpl} to ensure the seed gets placed into the general result map.
Since I'm not running with an EchoPersonAttributeDaoImpl, would this perhaps be the cause of my issue? This isn't hilighted in any of the person directory readmes at all.
Here's to hoping this is it. I hope this report helps you guys.
-Jeff
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
---
- 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 cas-user+u...@apereo.org.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/63b2d387-f50f-429d-bf29-1411a0fb1372%40apereo.org.To unsubscribe from this group and stop receiving emails from it, send an email to cas-user+u...@apereo.org.
Misagh Moayyed
Nov 18, 2016, 3:24:38 PM11/18/16
to cas-...@apereo.org
Excellent analysis, thank you.
It’s worth a try, I guess, to see if adding Echo to the Cascading DAO removes the issue. I admit person-directory is mostly a mystery to most of us (and 5 does not use the Cascading DAO at all by default). Its evolution has been sinusy.
--Misagh
From: cas-...@apereo.org [mailto:cas-...@apereo.org] On Behalf Of Jeffrey Wong
Sent: Friday, November 18, 2016 12:01 PM
To: CAS Community <cas-...@apereo.org>
Jeffrey Wong
Nov 19, 2016, 3:03:46 AM11/19/16
to CAS Community, mmoa...@unicon.net
Now that I'm a bit more accustomed to spring injection, I'm going to use the simpler merge strategies, rather than cascading for the production environments, as the code for that looks a lot less hairy.
I'll try adding Echo in a test environment, and get back to you.
-Jeff
Jeffrey Wong
Nov 29, 2016, 9:16:44 PM11/29/16
to CAS Community
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)
Abylay
Feb 14, 2019, 4:02:44 AM2/14/19
to CAS Community
Hi.
I'm getting the same exception on CAS 5.2.0.
Does anyone know the solution?
I'm getting the same exception on CAS 5.2.0.
Does anyone know the solution?
On Wednesday, July 20, 2016 at 4:09:59 AM UTC+6, 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
- Website: https://apereo.github.io/cas
- Gitter Chatroom: https://gitter.im/apereo/cas
- List Guidelines: https://goo.gl/1VRrw7
- Contributions: https://goo.gl/mh7qDG
---
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.
Reply all
Reply to author
Forward
0 new messages