search

apereo / phpCAS

Apereo PHP CAS Client
https://apereo.github.io/phpCAS/
Apache License 2.0
796 stars 397 forks source link

imap reconnection failure #50

Closed andl76 closed 12 years ago

andl76 commented 12 years ago

Hi, i have casified a webmail/imap system. When i authenticate via cas to the webmail/imap system everything is working fine and fast. The system i am using is roundcube version 0.7.2, cas_authentication_plugin 0.4.2 and phpcas 1.3.1. An imapproxy for dovecot is also configured. Now i am facing the problem that after i have logged in and have a time of inactivity in the mailbox (after several minutes) the imap connection is breaking up. But, not always...Thats the point where i get confused. Sometimes the connection is still there after a little delay of a few seconnds, but most of the time its breaking up.

mailcas.company.de is the webmail/imap-server. cas.company.de is the cas server.

Has anyone got an idea on this kind of failure?

The logs of the cas server show the following after a succesful reconnection:

2012-08-09 16:38:01,153 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] - ServiceTicket [ST-89-0TyHCUamcbb0jfdlFzyv-cas] does not exist. 2012-08-09 16:38:01,154 INFO [com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - Audit trail record BEGIN

WHO: audit:unknown WHAT: ST-89-0TyHCUamcbb0jfdlFzyv-cas ACTION: SERVICE_TICKET_VALIDATE_FAILED APPLICATION: CAS WHEN: Thu Aug 09 16:38:01 CEST 2012 CLIENT IP ADDRESS: xxx.xxxxxx.xxx SERVER IP ADDRESS: cas.company.de

2012-08-09 16:38:03,332 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] - Granted proxy ticket [ST-90-BsQKFu2pluddBa7CXQI4-cas] for service [imap://mailcas.company.de] for user [user] 2012-08-09 16:38:03,332 INFO [com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - Audit trail record BEGIN

WHO: https://mailcas.company.de/?_action=pgtcallback WHAT: ST-90-BsQKFu2pluddBa7CXQI4-cas for imap://mailcas.company.de ACTION: SERVICE_TICKET_CREATED APPLICATION: CAS WHEN: Thu Aug 09 16:38:03 CEST 2012 CLIENT IP ADDRESS: xxx.xxxxxx.xxx SERVER IP ADDRESS: cas.company.de

2012-08-09 16:38:07,485 INFO [com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - Audit trail record BEGIN

WHO: audit:unknown WHAT: ST-90-BsQKFu2pluddBa7CXQI4-cas ACTION: SERVICE_TICKET_VALIDATED APPLICATION: CAS WHEN: Thu Aug 09 16:38:07 CEST 2012 CLIENT IP ADDRESS: xxx.xxxxxx.xxx SERVER IP ADDRESS: cas.company.de

The auth.log of the webmail/imap system looks like:

Aug 9 16:38:01 mailcas PAM_cas[31540]: invalid option 'debug' Aug 9 16:38:01 mailcas PAM_cas[31540]: We use SSL as configured Aug 9 16:38:01 mailcas PAM_cas[31540]: We connect to host cas.company.de Aug 9 16:38:01 mailcas PAM_cas[31540]: ---- request :#012GET /cas/proxyValidate?ticket=ST-89-0TyHCUamcbb0jfdlFzyv-cas&service=imap://mailcas.company.de HTTP/1.1#012Connection: close#012Host: cas.company.de#012#012 Aug 9 16:38:01 mailcas PAM_cas[31540]: ---- response :#012HTTP/1.1 200 OK#015#012Date: Thu, 09 Aug 2012 14:38:01 GMT#015#012 Server: Apache/2.2.16 (Debian)#015#012Content-Language: en-US#015#012Content-Length: 231#015#012Connection: close#015#012Content-Type: text/plain; charset=UTF-8#015#012#015#012#012#011

#012#011#011ticket 'ST-89-0TyHCUamcbb0jfdlFzyv-cas' not recognized#012#011/cas:authenticationFailure#012/cas:serviceResponse Aug 9 16:38:01 mailcas PAM_cas[31540]: authentication failure for user 'user' : bad CAS ticket. PT=ST-89-0TyHCUamcbb0jfdlFzyv-cas Aug 9 16:38:01 mailcas auth[31540]: pam_ldap(dovecot:auth): nslcd authentication; user=user Aug 9 16:38:01 mailcas auth[31540]: pam_ldap(dovecot:auth): Authentication failure; user=user Aug 9 16:38:07 mailcas auth[31540]: PAM unable to dlopen(/lib/security/pam_passwdqc.so): /lib/security/pam_passwdqc.so: cannot open shared object file: No such file or directory Aug 9 16:38:07 mailcas auth[31540]: PAM adding faulty module: /lib/security/pam_passwdqc.so Aug 9 16:38:07 mailcas auth[31540]: PAM unable to dlopen(/lib/security/pam_tmpdir.so): /lib/security/pam_tmpdir.so: cannot open shared object file: No such file or directory Aug 9 16:38:07 mailcas auth[31540]: PAM adding faulty module: /lib/security/pam_tmpdir.so Aug 9 16:38:07 mailcas PAM_cas[31540]: invalid option 'debug' Aug 9 16:38:07 mailcas PAM_cas[31540]: We use SSL as configured Aug 9 16:38:07 mailcas PAM_cas[31540]: We connect to host cas.company.de Aug 9 16:38:07 mailcas PAM_cas[31540]: ---- request :#012GET /cas/proxyValidate?ticket=ST-90-BsQKFu2pluddBa7CXQI4-cas&service=imap://mailcas.company.de HTTP/1.1#012Connection: close#012Host: cas.company.de#012#012 Aug 9 16:38:07 mailcas PAM_cas[31540]: ---- response :#012HTTP/1.1 200 OK#015#012 Date: Thu, 09 Aug 2012 14:38:07 GMT#015#012Server: Apache/2.2.16 (Debian)#015#012Content-Language: en-US#015#012 Content-Length: 298#015#012Connection: close#015#012Content-Type: text/html; charset=UTF-8#015#012#015#012#012#011cas:authenticationSuccess#012#011#011 cas:useruser/cas:user#012#012#012#011#011cas:proxies#012#012#011#011#011cas:proxyhttps://mailcas.company.de/?_action=pgtcallback/cas:proxy#012#012#011#011/cas:proxies#012#012#011/cas:authenticationSuccess#012/cas:serviceResponse Aug 9 16:38:07 mailcas PAM_cas[31540]: USER 'user' AUTHENTICATED WITH CAS PT:ST-90-BsQKFu2pluddBa7CXQI4-cas But when the reconnection is failing, the server logs show: 2012-08-09 15:53:24,822 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] - ServiceTicket [ST-79-lJgAsbSLrHUPsFJIC9Fs-cas] does not exist. 2012-08-09 15:53:24,823 INFO [com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - Audit trail record BEGIN WHO: audit:unknown WHAT: ST-79-lJgAsbSLrHUPsFJIC9Fs-cas ACTION: SERVICE_TICKET_VALIDATE_FAILED APPLICATION: CAS WHEN: Thu Aug 09 15:53:24 CEST 2012 CLIENT IP ADDRESS: xxx.xxxxxx.xxx SERVER IP ADDRESS: cas.company.de 2012-08-09 15:53:26,482 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] - Granted proxy ticket [ST-80-41E7JKc2LpBlxPgUmWma-cas] for service [imap://mailcas.company.de] for user [user] 2012-08-09 15:53:26,483 INFO [com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - Audit trail record BEGIN WHO: https://mailcas.company.de/?_action=pgtcallback WHAT: ST-80-41E7JKc2LpBlxPgUmWma-cas for imap://mailcas.company.de ACTION: SERVICE_TICKET_CREATED APPLICATION: CAS WHEN: Thu Aug 09 15:53:26 CEST 2012 CLIENT IP ADDRESS: xxx.xxxxxx.xxx SERVER IP ADDRESS: cas.company.de 2012-08-09 15:53:32,408 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] - Granted proxy ticket [ST-81-77WyEIIIo7vL1nadcBlx-cas] for service [imap://mailcas.company.de] for user [user] 2012-08-09 15:53:32,409 INFO [com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - Audit trail record BEGIN WHO: https://mailcas.company.de/?_action=pgtcallback WHAT: ST-81-77WyEIIIo7vL1nadcBlx-cas for imap://mailcas.company.de ACTION: SERVICE_TICKET_CREATED APPLICATION: CAS WHEN: Thu Aug 09 15:53:32 CEST 2012 CLIENT IP ADDRESS: xxx.xxxxxx.xxx SERVER IP ADDRESS: cas.company.de 2012-08-09 15:53:33,382 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] - Granted proxy ticket [ST-82-4qNh2S3icke2awZiAd6S-cas] for service [imap://mailcas.company.de] for user [user] 2012-08-09 15:53:33,383 INFO [com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - Audit trail record BEGIN WHO: https://mailcas.company.de/?_action=pgtcallback WHAT: ST-82-4qNh2S3icke2awZiAd6S-cas for imap://mailcas.company.de ACTION: SERVICE_TICKET_CREATED APPLICATION: CAS WHEN: Thu Aug 09 15:53:33 CEST 2012 CLIENT IP ADDRESS: xxx.xxxxxx.xxx SERVER IP ADDRESS: cas.company.de 2012-08-09 15:53:40,734 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] - Granted service ticket [ST-83-zHDa6i0NGUYbjloAygLF-cas] for service [https://mailcas.company.de/?_task=mail&_action=login] for user [user] 2012-08-09 15:53:40,735 INFO [com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - Audit trail record BEGIN WHO: user WHAT: ST-83-zHDa6i0NGUYbjloAygLF-cas for https://mailcas.company.de/?_task=mail&_action=login ACTION: SERVICE_TICKET_CREATED APPLICATION: CAS WHEN: Thu Aug 09 15:53:40 CEST 2012 CLIENT IP ADDRESS: xxx.xxxxxx.xxx SERVER IP ADDRESS: cas.company.de 2012-08-09 15:53:41,226 INFO [org.jasig.cas.authentication.AuthenticationManagerImpl] - AuthenticationHandler: org.jasig.cas.authentication.handler.support.HttpBasedServiceCredentialsAuthenticationHandler successfully authenticated the user which provided the following credentials: [callbackUrl: https://mailcas.company.de/?_action=pgtcallback] 2012-08-09 15:53:41,229 INFO [org.jasig.cas.authentication.AuthenticationManagerImpl] - Resolved principal https://mailcas.company.de/?_action=pgtcallback 2012-08-09 15:53:41,229 INFO [org.jasig.cas.authentication.AuthenticationManagerImpl] - Principal found: https://mailcas.company.de/?_action=pgtcallback 2012-08-09 15:53:41,229 INFO [com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - Audit trail record BEGIN WHO: [callbackUrl: https://mailcas.company.de/?_action=pgtcallback] WHAT: supplied credentials: [callbackUrl: https://mailcas.company.de/?_action=pgtcallback] ACTION: AUTHENTICATION_SUCCESS APPLICATION: CAS WHEN: Thu Aug 09 15:53:41 CEST 2012 CLIENT IP ADDRESS: xxx.xxxxxx.xxx SERVER IP ADDRESS: cas.company.de 2012-08-09 15:53:41,230 INFO [com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - Audit trail record BEGIN WHO: user WHAT: TGT-16-qUWh1p9PIOgC9YCYE0aITT7XOcC0D6J2zqFAtzUx0aqHZNAExC-cas ACTION: PROXY_GRANTING_TICKET_CREATED APPLICATION: CAS WHEN: Thu Aug 09 15:53:41 CEST 2012 CLIENT IP ADDRESS: xxx.xxxxxx.xxx SERVER IP ADDRESS: cas.company.de 2012-08-09 15:53:41,231 INFO [com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - Audit trail record BEGIN WHO: audit:unknown WHAT: ST-83-zHDa6i0NGUYbjloAygLF-cas ACTION: SERVICE_TICKET_VALIDATED APPLICATION: CAS WHEN: Thu Aug 09 15:53:41 CEST 2012 CLIENT IP ADDRESS: xxx.xxxxxx.xxx SERVER IP ADDRESS: cas.company.de 2012-08-09 15:53:41,512 INFO [org.jasig.cas.services.DefaultServicesManagerImpl] - Reloading registered services. 2012-08-09 15:53:41,513 INFO [org.jasig.cas.services.DefaultServicesManagerImpl] - Loaded 4 services. 2012-08-09 15:53:41,648 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] - Granted proxy ticket [ST-84-lxqrQ7NDgQ3XraUaMe5U-cas] for service [imap://mailcas.company.de] for user [user] 2012-08-09 15:53:41,649 INFO [com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - Audit trail record BEGIN WHO: https://mailcas.company.de/?_action=pgtcallback WHAT: ST-84-lxqrQ7NDgQ3XraUaMe5U-cas for imap://mailcas.company.de ACTION: SERVICE_TICKET_CREATED APPLICATION: CAS WHEN: Thu Aug 09 15:53:41 CEST 2012 CLIENT IP ADDRESS: xxx.xxxxxx.xxx SERVER IP ADDRESS: cas.company.de 2012-08-09 15:53:41,770 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] - Granted proxy ticket [ST-85-xLG3RZxxFfbkjNJcHoTk-cas] for service [imap://mailcas.company.de] for user [user] 2012-08-09 15:53:41,771 INFO [com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - Audit trail record BEGIN WHO: https://mailcas.company.de/?_action=pgtcallback WHAT: ST-85-xLG3RZxxFfbkjNJcHoTk-cas for imap://mailcas.company.de ACTION: SERVICE_TICKET_CREATED APPLICATION: CAS WHEN: Thu Aug 09 15:53:41 CEST 2012 CLIENT IP ADDRESS: xxx.xxxxxx.xxx SERVER IP ADDRESS: cas.company.de 2012-08-09 15:53:51,326 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] - Granted proxy ticket [ST-86-qOb7b9vcwx7RaZBCc6nO-cas] for service [imap://mailcas.company.de] for user [user] 2012-08-09 15:53:51,328 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] - Granted proxy ticket [ST-87-DnARGllrslnfTKQ3CfvL-cas] for service [imap://mailcas.company.de] for user [user] 2012-08-09 15:53:51,329 INFO [com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - Audit trail record BEGIN WHO: https://mailcas.company.de/?_action=pgtcallback WHAT: ST-86-qOb7b9vcwx7RaZBCc6nO-cas for imap://mailcas.company.de ACTION: SERVICE_TICKET_CREATED APPLICATION: CAS WHEN: Thu Aug 09 15:53:51 CEST 2012 CLIENT IP ADDRESS: xxx.xxxxxx.xxx SERVER IP ADDRESS: cas.company.de 2012-08-09 15:53:51,330 INFO [com.github.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - Audit trail record BEGIN WHO: https://mailcas.company.de/?_action=pgtcallback WHAT: ST-87-DnARGllrslnfTKQ3CfvL-cas for imap://mailcas.company.de ACTION: SERVICE_TICKET_CREATED APPLICATION: CAS WHEN: Thu Aug 09 15:53:51 CEST 2012 CLIENT IP ADDRESS: xxx.xxxxxx.xxx SERVER IP ADDRESS: cas.company.de The auth.log of a failed reconnection shows: Aug 9 15:53:24 mailcas PAM_cas[31410]: invalid option 'debug' Aug 9 15:53:24 mailcas PAM_cas[31410]: We use SSL as configured Aug 9 15:53:24 mailcas PAM_cas[31410]: We connect to host cas.company.de Aug 9 15:53:24 mailcas PAM_cas[31410]: ---- request :#012GET /cas/proxyValidate?ticket=ST-79-lJgAsbSLrHUPsFJIC9Fs-cas&service=imap://mailcas.company.de HTTP/1.1#012Connection: close#012Host: cas.company.de#012#012 Aug 9 15:53:24 mailcas PAM_cas[31410]: ---- response :#012HTTP/1.1 200 OK#015#012Date: Thu, 09 Aug 2012 13:53:24 GMT#015#012 Server: Apache/2.2.16 (Debian)#015#012Content-Language: en-US#015#012Content-Length: 231#015#012 Connection: close#015#012Content-Type: text/plain;charset=UTF-8#015#012#015#012 #012#011#012#011#011ticket 'ST-79-lJgAsbSLrHUPsFJIC9Fs-cas' not recognized#012#011/cas:authenticationFailure#012/cas:serviceResponse Aug 9 15:53:24 mailcas PAM_cas[31410]: authentication failure for user 'user' : bad CAS ticket. PT=ST-79-lJgAsbSLrHUPsFJIC9Fs-cas Aug 9 15:53:24 mailcas auth[31410]: pam_ldap(dovecot:auth): nslcd authentication; user=user Aug 9 15:53:24 mailcas auth[31410]: pam_ldap(dovecot:auth): Authentication failure; user=user
jfritschi commented 12 years ago

The imap support of phpcas is rather crude and there are some issues with connection caching (#9). This may be related to how php caches imap connections. I guess you will have to do some deep digging in the phpcas debug logs in concert with the CAS server to figure out why this happens.

I don't have a woring IMAP setup to help much. IMAP has always been one of the features that very littly people use and is probably one of the areas that could use some improvement.

andl76 commented 12 years ago

Thanks for the hints. I configured some settings on the cas-server, in the file ticketExpirationPolicies.xml. There i set the following values for testing:

bean id="serviceTicketExpirationPolicy" class="org.jasig.cas.ticket.support.MultiTimeUseOrTimeoutExpirationPolicy
    <!-- This argument is the number of times that a ticket can be used before its considered expired. -->
    <constructor-arg
        index="0"
        value="2" />
    <!-- This argument is the time a ticket can exist before its considered expired.  -->
    <constructor-arg
        index="1"
        value="600000" />
</bean>

With this values the reconnection with the same ST is allowed twice with an inactivity interval of 10 minutes. This improves the login time, but decreases the security. But this is still not the real solution like one should do, right? Another question on this: Is it possible that the proxy mechanism is not working properly? I am asking because, i guess some peolpe are running some imap-system with cas succesfully. But did they had the same problems?

jfritschi commented 12 years ago

I think the key problem is how both phpcas and php cache credentials. This is my current take on the situation:

php caches imap connection by (ip,port, username, password) so that even though php is stateless another access to the same imap account reuses an already open imap connection. php just keeps the session open in the background and the user usually has the password stored in the session variable. If the cached connection is already dropped he is simply reconnected with his caches credentials.

With phpcas and proxy tickets a new complexity is introduced. The PT acts as a password that is transmitted instead of a normal password. But is only one time usable and this creates a problem. To cached imap connections the PT has to be used again so that the server side connection cache lookup works. It's actually not used for authentication but only for the cache lookup. If the cached entries expire the problem begins. Php tries to reuse the old PT which is of course invalid. For php it looks like the password is invalid. The is the point where phpcas need to get a net PT an reestablish a connection.

Since no one from the phpcas developer currently has an casified imap it's no very much tested and i think it's very buggy overall. Especially since the original imap support was developed when php didn't have caching. Unless someone with an casified imap actually debugs the current implementation and fixes some of the timeout/caching problems it will simply be as-is. Not very nice but it's rarely used feature and unless someone like yourself fixes it it will probably stay the way it is. :(

andl76 commented 12 years ago

Thanks for the detailed information. I finally solved the issue after i got more information about the caching method principle. The final hints are described here: https://github.com/dfwarden/Roundcube-CAS-Authn/issues/1#issuecomment-8457920

TBG-FR commented 2 years ago

@andl76 I bet you used "Dovecot's authentication caching feature or an intermediate caching IMAP proxy" as said in dfwarden's comment, but if you solved this issue in another way (with some php cache fixes), I'd like to hear it 😉