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?
On Wednesday, August 24, 2016 at 10:34:11 PM UTC-7, Misagh Moayyed wrote: > > 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 > > From: Jeffrey Wong <[email protected]> <javascript:> > Reply: Jeffrey Wong <[email protected]> <javascript:> > Date: August 24, 2016 at 2:20:36 PM > To: CAS Community <[email protected]> <javascript:> > Cc: [email protected] <javascript:> <[email protected]> <javascript:> > Subject: Re: [cas-user] After a month, no tickets created in 4.2.2? > > 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. > > On Tuesday, August 23, 2016 at 8:54:29 PM UTC-7, Misagh Moayyed wrote: >> >> 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 >> >> From: Jeffrey Wong <[email protected]> >> Reply: Jeffrey Wong <[email protected]> >> Date: August 23, 2016 at 2:33:34 PM >> To: CAS Community <[email protected]> >> Cc: [email protected] <[email protected]> >> Subject: Re: [cas-user] After a month, no tickets created in 4.2.2? >> >> 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. >> >> On Tuesday, August 23, 2016 at 2:04:51 PM UTC-7, Jeffrey Wong wrote: >>> >>> 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. >>> >>> On Monday, August 22, 2016 at 10:13:38 PM UTC-7, Misagh Moayyed wrote: >>>> >>>> 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 >>>> >>>> From: Jeffrey Wong <[email protected]> >>>> Reply: Jeffrey Wong <[email protected]> >>>> Date: August 22, 2016 at 3:50:03 PM >>>> To: CAS Community <[email protected]> >>>> Cc: [email protected] <[email protected]> >>>> Subject: Re: [cas-user] After a month, no tickets created in 4.2.2? >>>> >>>> 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. >>>> >>>> On Thursday, July 21, 2016 at 11:24:12 PM UTC-7, Misagh Moayyed wrote: >>>>> >>>>> 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 >>>>> >>>>> From: Jeffrey Wong <[email protected]> >>>>> Reply: Jeffrey Wong <[email protected]> >>>>> Date: July 20, 2016 at 3:27:17 PM >>>>> To: CAS Community <[email protected]> >>>>> Cc: [email protected] <[email protected]> >>>>> Subject: Re: [cas-user] After a month, no tickets created in 4.2.2? >>>>> >>>>> 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? >>>>> >>>>> On Wednesday, July 20, 2016 at 2:31:37 AM UTC-7, Misagh Moayyed wrote: >>>>>> >>>>>> 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 >>>>>> >>>>>> From: Jeffrey Wong <[email protected]> >>>>>> Reply: Jeffrey Wong <[email protected]> >>>>>> Date: July 19, 2016 at 3:10:05 PM >>>>>> To: CAS Community <[email protected]> >>>>>> Subject: [cas-user] After a month, no tickets created in 4.2.2? >>>>>> >>>>>> 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 >>>>>> -- >>>>>> You received this message because you are subscribed to the Google >>>>>> Groups "CAS Community" group. >>>>>> To unsubscribe from this group and stop receiving emails from it, >>>>>> send an email to [email protected]. >>>>>> To post to this group, send email to [email protected]. >>>>>> 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 >>>>>> >>>>>> <https://groups.google.com/a/apereo.org/d/msgid/cas-user/23b96c4d-0997-4da1-9051-7ddf1560e8bb%40apereo.org?utm_medium=email&utm_source=footer> >>>>>> . >>>>>> For more options, visit >>>>>> https://groups.google.com/a/apereo.org/d/optout. >>>>>> >>>>>> -- >>>>> You received this message because you are subscribed to the Google >>>>> Groups "CAS Community" group. >>>>> To unsubscribe from this group and stop receiving emails from it, send >>>>> an email to [email protected]. >>>>> To post to this group, send email to [email protected]. >>>>> 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/c879c072-5844-48af-8d62-ce868f6c738e%40apereo.org >>>>> >>>>> <https://groups.google.com/a/apereo.org/d/msgid/cas-user/c879c072-5844-48af-8d62-ce868f6c738e%40apereo.org?utm_medium=email&utm_source=footer> >>>>> . >>>>> For more options, visit >>>>> https://groups.google.com/a/apereo.org/d/optout. >>>>> >>>>> -- >>>> You received this message because you are subscribed to the Google >>>> Groups "CAS Community" group. >>>> To unsubscribe from this group and stop receiving emails from it, send >>>> an email to [email protected]. >>>> To post to this group, send email to [email protected]. >>>> 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/d37ce2b3-3d16-437d-8b9b-8d243f38237c%40apereo.org >>>> >>>> <https://groups.google.com/a/apereo.org/d/msgid/cas-user/d37ce2b3-3d16-437d-8b9b-8d243f38237c%40apereo.org?utm_medium=email&utm_source=footer> >>>> . >>>> For more options, visit https://groups.google.com/a/apereo.org/d/optout >>>> . >>>> >>>> -- >> You received this message because you are subscribed to the Google Groups >> "CAS Community" group. >> To unsubscribe from this group and stop receiving emails from it, send an >> email to [email protected]. >> To post to this group, send email to [email protected]. >> 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/ccf91db7-b2c6-47bb-b4a9-1f269e01dc66%40apereo.org >> >> <https://groups.google.com/a/apereo.org/d/msgid/cas-user/ccf91db7-b2c6-47bb-b4a9-1f269e01dc66%40apereo.org?utm_medium=email&utm_source=footer> >> . >> For more options, visit https://groups.google.com/a/apereo.org/d/optout. >> >> -- > You received this message because you are subscribed to the Google Groups > "CAS Community" group. > To unsubscribe from this group and stop receiving emails from it, send an > email to [email protected] <javascript:>. > To post to this group, send email to [email protected] <javascript:>. > 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/3ea99762-8912-4812-b892-49b76529f90e%40apereo.org > > <https://groups.google.com/a/apereo.org/d/msgid/cas-user/3ea99762-8912-4812-b892-49b76529f90e%40apereo.org?utm_medium=email&utm_source=footer> > . > For more options, visit https://groups.google.com/a/apereo.org/d/optout. > > -- You received this message because you are subscribed to the Google Groups "CAS Community" group. To unsubscribe from this group and stop receiving emails from it, send an email to [email protected]. To post to this group, send email to [email protected]. 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/a46a434e-e4d3-4726-8d4d-4214be1d12bb%40apereo.org. For more options, visit https://groups.google.com/a/apereo.org/d/optout.
