search

apereo / mod_auth_cas

An Apache httpd module for integrating with Apereo CAS Server project.
https://www.apereo.org/projects/cas
147 stars 97 forks source link

Session invalid after idle time less than what is defined. #151

Closed MattAtTTU closed 6 years ago

MattAtTTU commented 6 years ago

We have a complex configuration which includes Apache 2.4 running mod_auth_cas-1.1.3. The web server is protected with CAS and once a user authenticated, the REMOTE_USER header is passed on to another application which actually authenticates the user and provisions roles, etc.

We have our times set as follows in auth_cas.conf:

CASIdleTimeout 7200 CASTimeout 28800

When a user logs in and authenticates, we see the user's IP address and username in the access logs as we should. However, after the user sits idle for a period around one hour, the sessions becomes invalid and causes the application to function improperly. We do see CAS redirects in header captures which is why we're sure it's an invalid session.

My question is why do we see timeouts after one hour when all timeouts that we know of (application, CAS and mod_auth_cas) are configured for at least two hours? Have we missed something? Any help would be greatly appreciated.

Here is an example of the access log when we first login to the application without sitting idle:

10.10.10.10 - username [14/Aug/2018:14:53:32 -0500]

Here is an example after being idle for one hour and trying to make another request:

10.10.10.10 - - [14/Aug/2018:16:18:55 -0500]

Also, I've enabled debugging for the virtual host and mod_auth_cas module and no additional information is present in the logs, at least that I can find.

dhawes commented 6 years ago

Make sure that you have both "LogLevel debug" and "CASDebug On" in your config.

The logs should give us some insight into what is going on.

MattAtTTU commented 6 years ago

I have LogLevel debug in the virtual host config and CASDebug On in the auth_cas.conf. Is that what you’re referring to? If so, I’d be happy to share some of the logs. I haven’t seen anything jump out at me.

From: David Hawes notifications@github.com Sent: Wednesday, August 15, 2018 5:46:26 PM To: apereo/mod_auth_cas Cc: Thompson, Matt; Author Subject: Re: [apereo/mod_auth_cas] Session invalid after idle time less than what is defined. (#151)

Make sure that you have both "LogLevel debug" and "CASDebug On" in your config.

The logs should give us some insight into what is going on.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHubhttps://na01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fapereo%2Fmod_auth_cas%2Fissues%2F151%23issuecomment-413362934&data=02%7C01%7Cmatt.thompson%40ttu.edu%7C97a8b6822a134b2823b008d60300ef78%7C178a51bf8b2049ffb65556245d5c173c%7C0%7C0%7C636699699918566780&sdata=G43aYTGm1wBdDKzjZvh3FM9LF0ER9aMoxXmh%2FivQId8%3D&reserved=0, or mute the threadhttps://na01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fnotifications%2Funsubscribe-auth%2FAVniXX8FtYMgsmcSCcCI7vpNsdJQLQcVks5uRKTCgaJpZM4V9O3-&data=02%7C01%7Cmatt.thompson%40ttu.edu%7C97a8b6822a134b2823b008d60300ef78%7C178a51bf8b2049ffb65556245d5c173c%7C0%7C0%7C636699699918576782&sdata=Zu%2BAyhGNRUkfbB%2F8NBlUW%2FZYrf9my%2BtbKm5PCssmx%2Bs%3D&reserved=0.

MattAtTTU commented 6 years ago

I think this is the logging information pertinent to the issue. The error about the cache not being able to be opened and the cookie being invalid looks interesting to me. What do you think?


[Wed Aug 15 14:46:23.535244 2018] [socache_shmcb:debug] [pid 7015] mod_socache_shmcb.c(522): AH00835: socache_shmcb_retrieve (0x51 -> subcache 17)
[Wed Aug 15 14:46:23.535256 2018] [socache_shmcb:debug] [pid 7015] mod_socache_shmcb.c(877): AH00851: shmcb_subcache_retrieve found no match
[Wed Aug 15 14:46:23.535259 2018] [socache_shmcb:debug] [pid 7015] mod_socache_shmcb.c(532): AH00836: leaving socache_shmcb_retrieve successfully
[Wed Aug 15 14:46:23.535279 2018] [ssl:debug] [pid 7015] ssl_engine_kernel.c(1890): [client 10.10.10.10:54667] AH02043: SSL virtual host for servername url.domain.com found
[Wed Aug 15 14:46:23.552102 2018] [ssl:debug] [pid 7015] ssl_engine_kernel.c(1823): [client 10.10.10.10:54667] AH02041: Protocol: TLSv1, Cipher: ECDHE-RSA-AES128-SHA (128/128 bits)
[Wed Aug 15 14:46:23.553017 2018] [ssl:debug] [pid 7015] ssl_engine_kernel.c(225): [client 10.10.10.10:54667] AH02034: Initial (No.1) HTTPS request received for child 29 (server url.domain.com:443), referer: https://url.domain.com/ibmcognos/bi/?perspective=Welcome
[Wed Aug 15 14:46:23.553097 2018] [authz_core:debug] [pid 7015] mod_authz_core.c(809): [client 10.10.10.10:54667] AH01626: authorization result of Require valid-user : denied (no authenticated user yet), referer: https://url.domain.com/ibmcognos/bi/?perspective=Welcome
[Wed Aug 15 14:46:23.553101 2018] [authz_core:debug] [pid 7015] mod_authz_core.c(809): [client 10.10.10.10:54667] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet), referer: https://url.domain.com/ibmcognos/bi/?perspective=Welcome
[Wed Aug 15 14:46:23.553107 2018] [:debug] [pid 7015] mod_auth_cas.c(2058): [client 10.10.10.10:54667] Entering cas_authenticate(), referer: https://url.domain.com/ibmcognos/bi/?perspective=Welcome
[Wed Aug 15 14:46:23.553122 2018] [:debug] [pid 7015] mod_auth_cas.c(1655): [client 10.10.10.10:54667] entering isValidCASCookie(), referer: https://url.domain.com/ibmcognos/bi/?perspective=Welcome
[Wed Aug 15 14:46:23.553124 2018] [:debug] [pid 7015] mod_auth_cas.c(892): [client 10.10.10.10:54667] entering readCASCacheFile(), referer: https://url.domain.com/ibmcognos/bi/?perspective=Welcome
[Wed Aug 15 14:46:23.553161 2018] [:debug] [pid 7015] mod_auth_cas.c(926): [client 10.10.10.10:54667] Cache entry '9f14614c6332e1ea9980d693885324aa' could not be opened, referer: https://url.domain.com/ibmcognos/bi/?perspective=Welcome
[Wed Aug 15 14:46:23.553163 2018] [:debug] [pid 7015] mod_auth_cas.c(1660): [client 10.10.10.10:54667] Cookie '9f14614c6332e1ea9980d693885324aa' is corrupt or invalid, referer: https://url.domain.com/ibmcognos/bi/?perspective=Welcome
MattAtTTU commented 6 years ago

This looks like what we're seeing. I can confirm Ajax calls are involved on our end. We're running the prefork MPM with Apache 2.4. I'm wondering if changing to Worker or Event would help.

https://groups.google.com/forum/#!topic/jasig-cas-user/zcngEDnWIUE

dhawes commented 6 years ago

Those errors could simply mean that the 9f14614c6332e1ea9980d693885324aa cookie file was deleted. Do you see any other reference to 9f14614c6332e1ea9980d693885324aa in the log file?

Does the file 9f14614c6332e1ea9980d693885324aa exist in your CASCookiePath?

MattAtTTU commented 6 years ago

No and no. I looked for it yesterday and it wasn’t there.

From: David Hawes notifications@github.com Sent: Thursday, August 16, 2018 5:33:43 PM To: apereo/mod_auth_cas Cc: Thompson, Matt; Author Subject: Re: [apereo/mod_auth_cas] Session invalid after idle time less than what is defined. (#151)

Those errors could simply mean that the 9f14614c6332e1ea9980d693885324aa cookie file was deleted. Do you see any other reference to 9f14614c6332e1ea9980d693885324aa in the log file?

Does the file 9f14614c6332e1ea9980d693885324aa exist in your CASCookiePath?

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHubhttps://na01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fapereo%2Fmod_auth_cas%2Fissues%2F151%23issuecomment-413704555&data=02%7C01%7Cmatt.thompson%40ttu.edu%7Cd62ca8e825e541b30b5608d603c852d8%7C178a51bf8b2049ffb65556245d5c173c%7C0%7C0%7C636700556262049829&sdata=T0DJGn5UhZZ918oXZFYjrQvALzwKjxjtUS2uV0pXS9Q%3D&reserved=0, or mute the threadhttps://na01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fnotifications%2Funsubscribe-auth%2FAVniXYO8PNtXN0OIMzFc1ubbfacpAZT3ks5uRfNHgaJpZM4V9O3-&data=02%7C01%7Cmatt.thompson%40ttu.edu%7Cd62ca8e825e541b30b5608d603c852d8%7C178a51bf8b2049ffb65556245d5c173c%7C0%7C0%7C636700556262049829&sdata=Jq0wGaS7EIw9Sul1Fe6v%2F1A4b6P1X2w1%2FGNpmEG3GTY%3D&reserved=0.

dhawes commented 6 years ago

You should see debug output when the cookie was created and when it was removed.

Try your test again and verify that your cookie file exists and is readable. If mod_auth_cas removes the file, you should see it in the logs.

MattAtTTU commented 6 years ago

I still can't find the cookie when the error about a corrupt cookie is shown. I've tested several times and it's never present in the cache. Many other cookies are so the cache is working.

Yesterday, I removed mod_auth_cas as installed from EPEL and built from source. Since then, I can't reproduce this issue when accessing the site directly through an SSL virtual host on the server. However, when access through a load balancer, which terminates SSL and sends traffic to an HTTP virtual host, I can still reproduce the issue. Would mod_auth_cas act differently when users access via HTTP vs. HTTPS? My virtual hosts are identical except for the SSL binding information in the SSL virtual host.

dhawes commented 6 years ago

I wouldn't expect a difference, but the LB does raise some questions.

Do you have multiple Apache nodes behind the LB? If so, are you using sticky sessions, and what is the timeout for these sessions?

MattAtTTU commented 6 years ago

Yes, we have multiple nodes (two to be exact). We do use session persistence based on client IP and I can confirm that the sessions are sticking to the web server they initially hit. The timeout is set at two hours so this issue is occurring prior to that happening.

From: David Hawes notifications@github.com Sent: Friday, August 17, 2018 5:05 PM To: apereo/mod_auth_cas mod_auth_cas@noreply.github.com Cc: Thompson, Matt Matt.Thompson@ttu.edu; Author author@noreply.github.com Subject: Re: [apereo/mod_auth_cas] Session invalid after idle time less than what is defined. (#151)

I wouldn't expect a difference, but the LB does raise some questions.

Do you have multiple Apache nodes behind the LB? If so, are you using sticky sessions, and what is the timeout for these sessions?

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHubhttps://na01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fapereo%2Fmod_auth_cas%2Fissues%2F151%23issuecomment-413999552&data=02%7C01%7Cmatt.thompson%40ttu.edu%7C392146003b364718aabf08d6048d7098%7C178a51bf8b2049ffb65556245d5c173c%7C0%7C0%7C636701402867883809&sdata=6GOdoBNoDnX7VYpsAwehz8DsLif8Wcrkd4CqS%2BowqHc%3D&reserved=0, or mute the threadhttps://na01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fnotifications%2Funsubscribe-auth%2FAVniXU5lvxP3ZNzTsbtFTOduqRw6eAMIks5uRz37gaJpZM4V9O3-&data=02%7C01%7Cmatt.thompson%40ttu.edu%7C392146003b364718aabf08d6048d7098%7C178a51bf8b2049ffb65556245d5c173c%7C0%7C0%7C636701402867893823&sdata=jgWdEdDrzMI8xx%2FQfBa%2F%2Fmx8hS1p3LfUMBj66y2WJJ8%3D&reserved=0.

MattAtTTU commented 6 years ago

Late on Friday, we redirected the main URL for the application directly to the web node on port 443. Since we were unable to reproduce the issue directly against 443 but could reproduce through the load balancer, we wanted to force all users directly to the web node. Unfortunately, we can now reproduce the issue directly against the web node on port 443. That has lead us to think the issue may be due to user load. Would the cookie cache be cleaned up based on size at some point?

dhawes commented 6 years ago

The cache is cleaned based on time. See CASCacheCleanInterval, which defaults to 30m.

When the cache is cleaned, you should see delete messages in your debug logs.

Let's be methodical.

  1. Login to your application.
  2. Note the cookie in your web browser.
  3. Verify that this file exits in your CASCookiePath.
  4. Wait for your CASIdleTimeout.
  5. Hit your application again.
  6. grep your debug logs for the cookie. Post them here.
  7. Does the file still exist in your CASCookiePath?
MattAtTTU commented 6 years ago

I have logged into the application, noted my cookie ID and verified it is in the path. My timeout is set at two hours. This typically happens after only one. I will try again in an hour or so and see if the issue occurs. If so, I will post cookie results and debug logs, if available.

MattAtTTU commented 6 years ago

After just over one hour, the timeout issue occurred. The cookie ID was the same in the browser but did not exist in the cache on the web server once the issue presented.

The apache error log with debug enabled has the following entries for the cookie. 

[Mon Aug 20 17:15:48.399964 2018] [auth_cas:debug] [pid 23912:tid 139825394996992] mod_auth_cas.c(811): [client 10.10.10.10:58895] Adding outgoing header: Set-Cookie: MOD_AUTH_CAS_S=8610f7d74075e007cb21792313450e42;Secure;Path=/; HttpOnly, referer: https://fs.domain.com/adfs/ls/wia?wa=wsignin1.0&wtrealm=https%3a%2f%2fauth.domain.com%2f&wctx=rm%3d0%26id%3dpassive%26ru%3d%252fsignin.aspx%253fredirect%253dhttps%25253A%25252F%25252Fcas.domain.com%25252Fsso3.4%25253FredirectUrl%25253D%2525252Fsso3.4%2525252Flogin%2525253Fservice%2525253Dhttps%252525253a%252525252f%252525252fcognos.domain.com%252525252fibmcognos&wct=2018-08-20T22%3a15%3a42Z
[Mon Aug 20 17:40:44.101345 2018] [auth_cas:debug] [pid 23913:tid 139825509398272] mod_auth_cas.c(1146): [client 100.43.57.27:63249] Processing cache file '8610f7d74075e007cb21792313450e42', referer: https://fs.domain.com/adfs/ls/wia?wa=wsignin1.0&wtrealm=https%3a%2f%2fauth.domain.com%2f&wctx=rm%3d0%26id%3dpassive%26ru%3d%252fsignin.aspx%253fredirect%253dhttps%25253A%25252F%25252Fcas.domain.com%25252Fsso3.4%25253FredirectUrl%25253D%2525252Fsso3.4%2525252Flogin%2525253Fservice%2525253Dhttps%252525253a%252525252f%252525252fcognos.domain.com%252525252fibmcognos&wct=2018-08-20T22%3a40%3a34Z
[Mon Aug 20 17:40:44.101358 2018] [auth_cas:debug] [pid 23913:tid 139825509398272] mod_auth_cas.c(930): [client 100.43.57.27:63249] Cache entry '8610f7d74075e007cb21792313450e42' could not be opened, referer: https://fs.domain.com/adfs/ls/wia?wa=wsignin1.0&wtrealm=https%3a%2f%2fauth.domain.com%2f&wctx=rm%3d0%26id%3dpassive%26ru%3d%252fsignin.aspx%253fredirect%253dhttps%25253A%25252F%25252Fcas.domain.com%25252Fsso3.4%25253FredirectUrl%25253D%2525252Fsso3.4%2525252Flogin%2525253Fservice%2525253Dhttps%252525253a%252525252f%252525252fcognos.domain.com%252525252fibmcognos&wct=2018-08-20T22%3a40%3a34Z
[Mon Aug 20 17:40:44.101364 2018] [auth_cas:debug] [pid 23913:tid 139825509398272] mod_auth_cas.c(1162): [client 100.43.57.27:63249] Removing corrupt cache entry '8610f7d74075e007cb21792313450e42', referer: https://fs.domain.com/adfs/ls/wia?wa=wsignin1.0&wtrealm=https%3a%2f%2fauth.domain.com%2f&wctx=rm%3d0%26id%3dpassive%26ru%3d%252fsignin.aspx%253fredirect%253dhttps%25253A%25252F%25252Fcas.domain.com%25252Fsso3.4%25253FredirectUrl%25253D%2525252Fsso3.4%2525252Flogin%2525253Fservice%2525253Dhttps%252525253a%252525252f%252525252fcognos.domain.com%252525252fibmcognos&wct=2018-08-20T22%3a40%3a34Z
[Mon Aug 20 18:23:27.615467 2018] [auth_cas:debug] [pid 23913:tid 139825243928320] mod_auth_cas.c(930): [client 10.10.10.10:62497] Cache entry '8610f7d74075e007cb21792313450e42' could not be opened, referer: https://cognos.domain.com/ibmcognos/bi/?perspective=InstanceWelcome
[Mon Aug 20 18:23:27.615470 2018] [auth_cas:debug] [pid 23913:tid 139825243928320] mod_auth_cas.c(1676): [client 10.10.10.10:62497] Cookie '8610f7d74075e007cb21792313450e42' is corrupt or invalid, referer: https://cognos.domain.com/ibmcognos/bi/?perspective=InstanceWelcome

Note that username, IP address and domain names have been changed for security reasons. Also, note that there are two domains in use. The application resides as domain.com while the federation services CAS calls reside at domain2.com. I don't think that's the issue because this issue doesn't always occur. I just wanted to point that out.

MattAtTTU commented 6 years ago

This appears to be where the issue occurs. The first request looks good and is accepted but the second is denied and the CAS redirect happens. I'm unsure why it behaves this way. 


[Mon Aug 20 17:15:41.081473 2018] [ssl:debug] [pid 23968:tid 139825327855360] ssl_engine_kernel.c(1890): [client 10.10.10.10:58879] AH02043: SSL virtual host for servername cognos.domain.com found
[Mon Aug 20 17:15:41.087477 2018] [ssl:debug] [pid 23968:tid 139825327855360] ssl_engine_kernel.c(1823): [client 10.10.10.10:58879] AH02041: Protocol: TLSv1, Cipher: ECDHE-RSA-AES128-SHA (128/128 bits)
[Mon Aug 20 17:15:41.089727 2018] [ssl:debug] [pid 23968:tid 139825327855360] ssl_engine_kernel.c(225): [client 10.10.10.10:58879] AH02034: Initial (No.1) HTTPS request received for child 206 (server cognos.domain.com:443)
[Mon Aug 20 17:15:41.089797 2018] [authz_core:debug] [pid 23968:tid 139825327855360] mod_authz_core.c(809): [client 10.10.10.10:58879] AH01626: authorization result of Require all granted: granted
[Mon Aug 20 17:15:41.089800 2018] [authz_core:debug] [pid 23968:tid 139825327855360] mod_authz_core.c(809): [client 10.10.10.10:58879] AH01626: authorization result of <RequireAny>: granted
[Mon Aug 20 17:15:41.089828 2018] [authz_core:debug] [pid 23968:tid 139825327855360] mod_authz_core.c(809): [client 10.10.10.10:58879] AH01626: authorization result of Require all granted: granted
[Mon Aug 20 17:15:41.089832 2018] [authz_core:debug] [pid 23968:tid 139825327855360] mod_authz_core.c(809): [client 10.10.10.10:58879] AH01626: authorization result of <RequireAny>: granted
[Mon Aug 20 17:15:41.388405 2018] [ssl:debug] [pid 23968:tid 139825327855360] ssl_engine_kernel.c(225): [client 10.10.10.10:58879] AH02034: Subsequent (No.2) HTTPS request received for child 206 (server cognos.domain.com:443)
[Mon Aug 20 17:15:41.388519 2018] [authz_core:debug] [pid 23968:tid 139825327855360] mod_authz_core.c(809): [client 10.10.10.10:58879] AH01626: authorization result of Require valid-user : denied (no authenticated user yet)
[Mon Aug 20 17:15:41.388524 2018] [authz_core:debug] [pid 23968:tid 139825327855360] mod_authz_core.c(809): [client 10.10.10.10:58879] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet)
[Mon Aug 20 17:15:41.388532 2018] [auth_cas:debug] [pid 23968:tid 139825327855360] mod_auth_cas.c(2076): [client 10.10.10.10:58879] Entering cas_authenticate()
[Mon Aug 20 17:15:41.388548 2018] [auth_cas:debug] [pid 23968:tid 139825327855360] mod_auth_cas.c(584): [client 10.10.10.10:58879] CAS Service 'https%3a%2f%2fcognos.domain.com%2fibmcognos'
[Mon Aug 20 17:15:41.388552 2018] [auth_cas:debug] [pid 23968:tid 139825327855360] mod_auth_cas.c(532): [client 10.10.10.10:58879] entering getCASLoginURL()
[Mon Aug 20 17:15:41.388557 2018] [auth_cas:debug] [pid 23968:tid 139825327855360] mod_auth_cas.c(509): [client 10.10.10.10:58879] entering getCASGateway()
[Mon Aug 20 17:15:41.388560 2018] [auth_cas:debug] [pid 23968:tid 139825327855360] mod_auth_cas.c(599): [client 10.10.10.10:58879] entering redirectRequest()
dhawes commented 6 years ago

This line is interesting:

[Mon Aug 20 17:40:44.101364 2018] [auth_cas:debug] [pid 23913:tid 139825509398272] mod_auth_cas.c(1162): [client 100.43.57.27:63249] Removing corrupt cache entry '8610f7d74075e007cb21792313450e42', referer: https://fs.domain.com/adfs/ls/wia?wa=wsignin1.0&wtrealm=https%3a%2f%2fauth.domain.com%2f&wctx=rm%3d0%26id%3dpassive%26ru%3d%252fsignin.aspx%253fredirect%253dhttps%25253A%25252F%25252Fcas.domain.com%25252Fsso3.4%25253FredirectUrl%25253D%2525252Fsso3.4%2525252Flogin%2525253Fservice%2525253Dhttps%252525253a%252525252f%252525252fcognos.domain.com%252525252fibmcognos&wct=2018-08-20T22%3a40%3a34Z

Presumably CASCleanCache() is called, the file is found in the cache directory, and then the file can't be read. When you open the file, does it look valid? Do file permissions look right? Does the file change before the cache is cleaned?

Can you post your Apache config?

MattAtTTU commented 6 years ago

The file has never been there after I receive the error so could not be opened. I was going to attempt to open it before reproducing the error today but early testing indicates that setting the CASCacheCleanInterval to 3 hours (timeout is configured at 2) has possibly resolved the issue. I had a session which sat idle for over an hour and was still able to access the site. This has not worked before. Also, my cookie was still present and unchanged in the cache. I will update with the results of further testing but it does seem like the CASCacheCleanInterval isn't as trivial as the documentation indicates.

CASCacheCleanInterval 10800

dhawes commented 6 years ago

What other mod_auth_cas logs are there around these times?

[Mon Aug 20 17:40:44.101345 2018] [auth_cas:debug] [pid 23913:tid 139825509398272] mod_auth_cas.c(1146): [client 100.43.57.27:63249] Processing cache file '8610f7d74075e007cb21792313450e42', referer: https://fs.domain.com/adfs/ls/wia?wa=wsignin1.0&wtrealm=https%3a%2f%2fauth.domain.com%2f&wctx=rm%3d0%26id%3dpassive%26ru%3d%252fsignin.aspx%253fredirect%253dhttps%25253A%25252F%25252Fcas.domain.com%25252Fsso3.4%25253FredirectUrl%25253D%2525252Fsso3.4%2525252Flogin%2525253Fservice%2525253Dhttps%252525253a%252525252f%252525252fcognos.domain.com%252525252fibmcognos&wct=2018-08-20T22%3a40%3a34Z
[Mon Aug 20 17:40:44.101358 2018] [auth_cas:debug] [pid 23913:tid 139825509398272] mod_auth_cas.c(930): [client 100.43.57.27:63249] Cache entry '8610f7d74075e007cb21792313450e42' could not be opened, referer: https://fs.domain.com/adfs/ls/wia?wa=wsignin1.0&wtrealm=https%3a%2f%2fauth.domain.com%2f&wctx=rm%3d0%26id%3dpassive%26ru%3d%252fsignin.aspx%253fredirect%253dhttps%25253A%25252F%25252Fcas.domain.com%25252Fsso3.4%25253FredirectUrl%25253D%2525252Fsso3.4%2525252Flogin%2525253Fservice%2525253Dhttps%252525253a%252525252f%252525252fcognos.domain.com%252525252fibmcognos&wct=2018-08-20T22%3a40%3a34Z
[Mon Aug 20 17:40:44.101364 2018] [auth_cas:debug] [pid 23913:tid 139825509398272] mod_auth_cas.c(1162): [client 100.43.57.27:63249] Removing corrupt cache entry '8610f7d74075e007cb21792313450e42', referer: https://fs.domain.com/adfs/ls/wia?wa=wsignin1.0&wtrealm=https%3a%2f%2fauth.domain.com%2f&wctx=rm%3d0%26id%3dpassive%26ru%3d%252fsignin.aspx%253fredirect%253dhttps%25253A%25252F%25252Fcas.domain.com%25252Fsso3.4%25253FredirectUrl%25253D%2525252Fsso3.4%2525252Flogin%2525253Fservice%2525253Dhttps%252525253a%252525252f%252525252fcognos.domain.com%252525252fibmcognos&wct=2018-08-20T22%3a40%3a34Z

I've been unable to reproduce this, so the more information about how the cache is getting corrupt (or removed) is useful. Periodically inspecting the cache file may tell us something about what is going on.

MDeeApp commented 6 years ago

Any news on this issue? I'm hitting nearly the same errors.

dhawes commented 6 years ago

If you can provide logs and a detailed account of what's going on with your cache, that would be helpful in determining what the issue is.

Better yet, if you can provide a way to reliably reproduce this issue with configuration details, that would be great. I still have been unable to reproduce this.

MattAtTTU commented 6 years ago

Sorry to leave this hanging. I've actually changed jobs and am no longer working on this issue. We ended up working away from mod_auth_cas to a vendor supported method anyway so not sure we would have been able to troubleshoot. I think this can be closed.