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)#15#012Content-Language: en-US#015#012Content-Length: 231#015#012Connection: close#015#012Content-Type: text/plain;
charset=UTF-8#015#012#015#012<cas:serviceResponse xmlns:cas='http://www.yale.edu/tp/cas'>#012#011
<cas:authenticationFailure code='INVALID_TICKET'>#12#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)#15#012Content-Language: en-US#015#012
Content-Length: 298#015#012Connection: close#015#012Content-Type: text/html;
charset=UTF-8#015#012#015#012<cas:serviceResponse xmlns:cas='http://www.yale.edu/tp/cas'>#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)#15#012Content-Language: en-US#015#012Content-Length: 231#015#012
Connection: close#015#012Content-Type: text/plain;charset=UTF-8#015#012#015#012
<cas:serviceResponse xmlns:cas='http://www.yale.edu/tp/cas'>#012#011<cas:authenticationFailure code='INVALID_TICKET'>#12#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