View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0002408SOGoWeb Mailpublic2013-09-06 06:452013-09-18 13:21
Reporterdani Assigned Tojraby 
PrioritynormalSeverityminorReproducibilityalways
Status closedResolutionopen 
Product Version2.0.7 
Fixed in Version2.1.0 
Summary0002408: CAS authentication hangs sogod
Description

I cannot make SOGo working with CAS authentication, tried on different setup (RHEL5 and RHEL6). Here's the situation

  • I have a working CAS server, tested successfuly with other applications (GLPI, Ejabberd + Jappix + pam_cas etc...). I'm not running JASIG CAS but LemonLDAP::NG as CAS server. I don't think it makes a difference, as LemonLDAP::NG implement the same CAS protocol, but I haven't tested with JASIG CAS

  • Withtout CAS authentication, SOGo is working great, I can login and access to all the modules. It's using an LDAP server as user source

  • I enable CAS auth adding this in /etc/sogo/sogo.conf:

    SOGoAuthenticationType = cas;
    SOGoCASServiceURL = "https://auth.domain.tld/cas/";

  • I checked everything from the installation guide: CAS URL is reachable from SOGo, SOGo URL is reacheable from the cas server, both can verify the certificate used by the other one, I have 10 workers

  • When I try to login with this new setup, SOGo login page redirects me to my CAS login page (/cas/login?service=https%3A%2F%2Fwebmail.domain.tld%2FSOGo%2Fso%2Findex)

  • Once I'm loged on my CAS server, it redirects me to SOGo with a ticket (https://webmail.domain.tld/SOGo/so/index?ticket=ST-4c09ac201153fcacce3f19143f45509f)

  • SOGo try to validate the ticket asking the CAS server /cas/serviceValidate?ticket=ST-4c09ac201153fcacce3f19143f45509f&service=https%3A%2F%2Fwebmail.domain.tld%2FSOGo%2Fso%2Findex&pgtUrl=https%3A%2F%2Fwebmail.domain.tld%2FSOGo%2FcasProxy

At this point, the worker handling this is hanging (100% CPU, no response, logs keep saying pid 5618 has been hanging in the same request for 1 minutes until the watchdog kills it).

My CAS server tries to call the pgt URL (/SOGo/casProxy?pgtIou=PGTIOU-bf3e756a8eb388b8a7d8190ab68c002b&pgtId=PGT-e8d54df73d43fd4829ebd088dff77135), SOGo logs show a 200 code for this request, but I'm not sure if cas is getting the correct answer.

I haven't installed the cas-proxy-validate.py script yet, i'd like to get things working before I look at how I can optimize it.

Attached is a backtrace of the hanged process, I hope it can help.

Let me know if you need more information.

Additional Information

RHEL6 x86_64
SOGo 2.0.7 from sogo-rhel6 repo

TagsNo tags attached.

Activities

2013-09-06 06:45

 

cas_bt.txt (23,750 bytes)    
[root@webmail ~]# gdb -p 15501
GNU gdb (GDB) Red Hat Enterprise Linux (7.2-60.el6_4.1)
Copyright (C) 2010 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Attaching to process 15501
Reading symbols from /usr/sbin/sogod...Reading symbols from /usr/lib/debug/usr/sbin/sogod.debug...done.
done.
Reading symbols from /usr/lib64/libSOGo.so.2...Reading symbols from /usr/lib/debug/usr/lib64/GNUstep/Frameworks/SOGo.framework/Versions/2/libSOGo.so.2.0.7.debug...done.
done.
Loaded symbols for /usr/lib64/libSOGo.so.2
Reading symbols from /usr/lib64/libOGoContentStore.so.0.9...Reading symbols from /usr/lib/debug/usr/lib64/libOGoContentStore.so.0.9.0.debug...done.
done.
Loaded symbols for /usr/lib64/libOGoContentStore.so.0.9
Reading symbols from /usr/lib64/libGDLContentStore.so.4.9...Reading symbols from /usr/lib/debug/usr/lib64/libGDLContentStore.so.4.9.0.debug...done.
done.
Loaded symbols for /usr/lib64/libGDLContentStore.so.4.9
Reading symbols from /usr/lib64/libGDLAccess.so.4.9...Reading symbols from /usr/lib/debug/usr/lib64/libGDLAccess.so.4.9.63.debug...done.
done.
Loaded symbols for /usr/lib64/libGDLAccess.so.4.9
Reading symbols from /usr/lib64/libWEExtensions.so.4.9...Reading symbols from /usr/lib/debug/usr/lib64/libWEExtensions.so.4.9.94.debug...done.
done.
Loaded symbols for /usr/lib64/libWEExtensions.so.4.9
Reading symbols from /usr/lib64/libNGCards.so.4.9...Reading symbols from /usr/lib/debug/usr/lib64/libNGCards.so.4.9.0.debug...done.
done.
Loaded symbols for /usr/lib64/libNGCards.so.4.9
Reading symbols from /usr/lib64/libNGObjWeb.so.4.9...Reading symbols from /usr/lib/debug/usr/lib64/libNGObjWeb.so.4.9.37.debug...done.
done.
Loaded symbols for /usr/lib64/libNGObjWeb.so.4.9
Reading symbols from /usr/lib64/libNGMime.so.4.9...Reading symbols from /usr/lib/debug/usr/lib64/libNGMime.so.4.9.3.debug...done.
done.
Loaded symbols for /usr/lib64/libNGMime.so.4.9
Reading symbols from /usr/lib64/libNGLdap.so.4.9...Reading symbols from /usr/lib/debug/usr/lib64/libNGLdap.so.4.9.35.debug...done.
done.
Loaded symbols for /usr/lib64/libNGLdap.so.4.9
Reading symbols from /usr/lib64/libNGStreams.so.4.9...Reading symbols from /usr/lib/debug/usr/lib64/libNGStreams.so.4.9.57.debug...done.
done.
Loaded symbols for /usr/lib64/libNGStreams.so.4.9
Reading symbols from /usr/lib64/libNGExtensions.so.4.9...Reading symbols from /usr/lib/debug/usr/lib64/libNGExtensions.so.4.9.203.debug...done.
done.
Loaded symbols for /usr/lib64/libNGExtensions.so.4.9
Reading symbols from /usr/lib64/libEOControl.so.4.9...Reading symbols from /usr/lib/debug/usr/lib64/libEOControl.so.4.9.74.debug...done.
done.
Loaded symbols for /usr/lib64/libEOControl.so.4.9
Reading symbols from /usr/lib64/libDOM.so.4.9...Reading symbols from /usr/lib/debug/usr/lib64/libDOM.so.4.9.24.debug...done.
done.
Loaded symbols for /usr/lib64/libDOM.so.4.9
Reading symbols from /usr/lib64/libSaxObjC.so.4.9...Reading symbols from /usr/lib/debug/usr/lib64/libSaxObjC.so.4.9.66.debug...done.
done.
Loaded symbols for /usr/lib64/libSaxObjC.so.4.9
Reading symbols from /usr/lib64/libgnustep-base.so.1.23...Reading symbols from /usr/lib/debug/usr/lib64/libgnustep-base.so.1.23.0.debug...done.
done.
Loaded symbols for /usr/lib64/libgnustep-base.so.1.23
Reading symbols from /lib64/libpthread.so.0...(no debugging symbols found)...done.
[Thread debugging using libthread_db enabled]
Loaded symbols for /lib64/libpthread.so.0
Reading symbols from /usr/lib64/libobjc.so.2...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libobjc.so.2
Reading symbols from /lib64/libm.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib64/libm.so.6
Reading symbols from /lib64/libgcc_s.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libgcc_s.so.1
Reading symbols from /lib64/libc.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib64/libc.so.6
Reading symbols from /usr/lib64/libmemcached.so.7...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libmemcached.so.7
Reading symbols from /usr/lib64/libSBJson.so.2...Reading symbols from /usr/lib/debug/usr/lib64/libSBJson.so.2.3.1.debug...done.
done.
Loaded symbols for /usr/lib64/libSBJson.so.2
Reading symbols from /usr/lib64/libcrypto.so.10...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libcrypto.so.10
Reading symbols from /usr/lib64/liblasso.so.3...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/liblasso.so.3
Reading symbols from /usr/lib64/libxmlsec1.so.1...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libxmlsec1.so.1
Reading symbols from /usr/lib64/libltdl.so.7...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libltdl.so.7
Reading symbols from /lib64/libgobject-2.0.so.0...(no debugging symbols found)...done.
Loaded symbols for /lib64/libgobject-2.0.so.0
Reading symbols from /usr/lib64/libxslt.so.1...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libxslt.so.1
Reading symbols from /lib64/libz.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libz.so.1
Reading symbols from /usr/lib64/libxml2.so.2...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libxml2.so.2
Reading symbols from /lib64/libglib-2.0.so.0...(no debugging symbols found)...done.
Loaded symbols for /lib64/libglib-2.0.so.0
Reading symbols from /lib64/libcrypt.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libcrypt.so.1
Reading symbols from /lib64/libldap-2.4.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libldap-2.4.so.2
Reading symbols from /lib64/liblber-2.4.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/liblber-2.4.so.2
Reading symbols from /usr/lib64/libssl.so.10...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libssl.so.10
Reading symbols from /usr/lib64/libffi.so.5...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libffi.so.5
Reading symbols from /lib64/libnsl.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libnsl.so.1
Reading symbols from /lib64/librt.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/librt.so.1
Reading symbols from /lib64/libdl.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libdl.so.2
Reading symbols from /lib64/ld-linux-x86-64.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
Reading symbols from /usr/lib64/libsasl2.so.2...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libsasl2.so.2
Reading symbols from /usr/lib64/libstdc++.so.6...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libstdc++.so.6
Reading symbols from /usr/lib64/libxmlsec1-openssl.so.1...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libxmlsec1-openssl.so.1
Reading symbols from /usr/lib64/libfreebl3.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libfreebl3.so
Reading symbols from /lib64/libresolv.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libresolv.so.2
Reading symbols from /usr/lib64/libssl3.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libssl3.so
Reading symbols from /usr/lib64/libsmime3.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libsmime3.so
Reading symbols from /usr/lib64/libnss3.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libnss3.so
Reading symbols from /usr/lib64/libnssutil3.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libnssutil3.so
Reading symbols from /lib64/libplds4.so...(no debugging symbols found)...done.
Loaded symbols for /lib64/libplds4.so
Reading symbols from /lib64/libplc4.so...(no debugging symbols found)...done.
Loaded symbols for /lib64/libplc4.so
Reading symbols from /lib64/libnspr4.so...(no debugging symbols found)...done.
Loaded symbols for /lib64/libnspr4.so
Reading symbols from /lib64/libgssapi_krb5.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libgssapi_krb5.so.2
Reading symbols from /lib64/libkrb5.so.3...(no debugging symbols found)...done.
Loaded symbols for /lib64/libkrb5.so.3
Reading symbols from /lib64/libcom_err.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libcom_err.so.2
Reading symbols from /lib64/libk5crypto.so.3...(no debugging symbols found)...done.
Loaded symbols for /lib64/libk5crypto.so.3
Reading symbols from /lib64/libkrb5support.so.0...(no debugging symbols found)...done.
Loaded symbols for /lib64/libkrb5support.so.0
Reading symbols from /lib64/libkeyutils.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libkeyutils.so.1
Reading symbols from /lib64/libselinux.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libselinux.so.1
Reading symbols from /usr/lib64/gconv/UTF-16.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/gconv/UTF-16.so
Reading symbols from /usr/lib64/gconv/UTF-32.so...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/gconv/UTF-32.so
Reading symbols from /lib64/libnss_files.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libnss_files.so.2
Reading symbols from /usr/lib64/GNUstep/SOGo/Appointments.SOGo/./Appointments...Reading symbols from /usr/lib/debug/usr/lib64/GNUstep/SOGo/Appointments.SOGo/Appointments.debug...done.
done.
Loaded symbols for /usr/lib64/GNUstep/SOGo/Appointments.SOGo/./Appointments
Reading symbols from /usr/lib64/libcurl.so.4...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libcurl.so.4
Reading symbols from /lib64/libidn.so.11...(no debugging symbols found)...done.
Loaded symbols for /lib64/libidn.so.11
Reading symbols from /usr/lib64/libssh2.so.1...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libssh2.so.1
Reading symbols from /usr/lib64/GNUstep/SOGo/Mailer.SOGo/./Mailer...Reading symbols from /usr/lib/debug/usr/lib64/GNUstep/SOGo/Mailer.SOGo/Mailer.debug...done.
done.
Loaded symbols for /usr/lib64/GNUstep/SOGo/Mailer.SOGo/./Mailer
Reading symbols from /usr/lib64/GNUstep/SOGo/CommonUI.SOGo/./CommonUI...Reading symbols from /usr/lib/debug/usr/lib64/GNUstep/SOGo/CommonUI.SOGo/CommonUI.debug...done.
done.
Loaded symbols for /usr/lib64/GNUstep/SOGo/CommonUI.SOGo/./CommonUI
Reading symbols from /usr/lib64/libSOGoUI.so.2.0...Reading symbols from /usr/lib/debug/usr/lib64/libSOGoUI.so.2.0.0.debug...done.
done.
Loaded symbols for /usr/lib64/libSOGoUI.so.2.0
Reading symbols from /usr/lib64/GNUstep/SOGo/MainUI.SOGo/./MainUI...Reading symbols from /usr/lib/debug/usr/lib64/GNUstep/SOGo/MainUI.SOGo/MainUI.debug...done.
done.
Loaded symbols for /usr/lib64/GNUstep/SOGo/MainUI.SOGo/./MainUI
Reading symbols from /usr/lib64/GNUstep/SOGo/AdministrationUI.SOGo/./AdministrationUI...Reading symbols from /usr/lib/debug/usr/lib64/GNUstep/SOGo/AdministrationUI.SOGo/AdministrationUI.debug...done.
done.
Loaded symbols for /usr/lib64/GNUstep/SOGo/AdministrationUI.SOGo/./AdministrationUI
Reading symbols from /usr/lib64/GNUstep/SoProducts-4.9/SoCore.sxp/./SoCore...Reading symbols from /usr/lib/debug/usr/lib64/GNUstep/SoProducts-4.9/SoCore.sxp/SoCore.debug...done.
done.
Loaded symbols for /usr/lib64/GNUstep/SoProducts-4.9/SoCore.sxp/./SoCore
Reading symbols from /usr/lib64/GNUstep/SOGo/Contacts.SOGo/./Contacts...Reading symbols from /usr/lib/debug/usr/lib64/GNUstep/SOGo/Contacts.SOGo/Contacts.debug...done.
done.
Loaded symbols for /usr/lib64/GNUstep/SOGo/Contacts.SOGo/./Contacts
Reading symbols from /usr/lib64/GNUstep/SOGo/MailPartViewers.SOGo/./MailPartViewers...Reading symbols from /usr/lib/debug/usr/lib64/GNUstep/SOGo/MailPartViewers.SOGo/MailPartViewers.debug...done.
done.
Loaded symbols for /usr/lib64/GNUstep/SOGo/MailPartViewers.SOGo/./MailPartViewers
Reading symbols from /usr/lib64/GNUstep/SOGo/MailerUI.SOGo/./MailerUI...Reading symbols from /usr/lib/debug/usr/lib64/GNUstep/SOGo/MailerUI.SOGo/MailerUI.debug...done.
done.
Loaded symbols for /usr/lib64/GNUstep/SOGo/MailerUI.SOGo/./MailerUI
Reading symbols from /usr/lib64/GNUstep/SOGo/PreferencesUI.SOGo/./PreferencesUI...Reading symbols from /usr/lib/debug/usr/lib64/GNUstep/SOGo/PreferencesUI.SOGo/PreferencesUI.debug...done.
done.
Loaded symbols for /usr/lib64/GNUstep/SOGo/PreferencesUI.SOGo/./PreferencesUI
Reading symbols from /usr/lib64/GNUstep/SOGo/ContactsUI.SOGo/./ContactsUI...Reading symbols from /usr/lib/debug/usr/lib64/GNUstep/SOGo/ContactsUI.SOGo/ContactsUI.debug...done.
done.
Loaded symbols for /usr/lib64/GNUstep/SOGo/ContactsUI.SOGo/./ContactsUI
Reading symbols from /usr/lib64/GNUstep/SOGo/SchedulerUI.SOGo/./SchedulerUI...Reading symbols from /usr/lib/debug/usr/lib64/GNUstep/SOGo/SchedulerUI.SOGo/SchedulerUI.debug...done.
done.
Loaded symbols for /usr/lib64/GNUstep/SOGo/SchedulerUI.SOGo/./SchedulerUI
Reading symbols from /usr/lib64/GNUstep/GDLAdaptors-4.9/MySQL.gdladaptor/./MySQL...Reading symbols from /usr/lib/debug/usr/lib64/GNUstep/GDLAdaptors-4.9/MySQL.gdladaptor/MySQL.debug...done.
done.
Loaded symbols for /usr/lib64/GNUstep/GDLAdaptors-4.9/MySQL.gdladaptor/./MySQL
Reading symbols from /usr/lib64/mysql/libmysqlclient.so.16...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/mysql/libmysqlclient.so.16
Reading symbols from /lib64/libnss_dns.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libnss_dns.so.2
Reading symbols from /usr/lib64/GNUstep/SaxDrivers-4.9/libxmlSAXDriver.sax/./libxmlSAXDriver...Reading symbols from /usr/lib/debug/usr/lib64/GNUstep/SaxDrivers-4.9/libxmlSAXDriver.sax/libxmlSAXDriver.debug...done.
done.
Loaded symbols for /usr/lib64/GNUstep/SaxDrivers-4.9/libxmlSAXDriver.sax/./libxmlSAXDriver
Reading symbols from /usr/lib64/GNUstep/Libraries/gnustep-base/Versions/1.23/Resources/SSL.bundle/./SSL...Reading symbols from /usr/lib/debug/usr/lib64/GNUstep/Libraries/gnustep-base/Versions/1.23/Resources/SSL.bundle/SSL.debug...done.
done.
Loaded symbols for /usr/lib64/GNUstep/Libraries/gnustep-base/Versions/1.23/Resources/SSL.bundle/./SSL
Reading symbols from /usr/lib64/GNUstep/WOxElemBuilders-4.9/WOExtensions.wox/./WOExtensions...Reading symbols from /usr/lib/debug/usr/lib64/GNUstep/WOxElemBuilders-4.9/WOExtensions.wox/WOExtensions.debug...done.
done.
Loaded symbols for /usr/lib64/GNUstep/WOxElemBuilders-4.9/WOExtensions.wox/./WOExtensions
Reading symbols from /usr/lib64/libWOExtensions.so.4.9...Reading symbols from /usr/lib/debug/usr/lib64/libWOExtensions.so.4.9.31.debug...done.
done.
Loaded symbols for /usr/lib64/libWOExtensions.so.4.9
Reading symbols from /usr/lib64/GNUstep/WOxElemBuilders-4.9/SOGoElements.wox/./SOGoElements...Reading symbols from /usr/lib/debug/usr/lib64/GNUstep/WOxElemBuilders-4.9/SOGoElements.wox/SOGoElements.debug...done.
done.
Loaded symbols for /usr/lib64/GNUstep/WOxElemBuilders-4.9/SOGoElements.wox/./SOGoElements
Reading symbols from /usr/lib64/GNUstep/WOxElemBuilders-4.9/WEExtensions.wox/./WEExtensions...Reading symbols from /usr/lib/debug/usr/lib64/GNUstep/WOxElemBuilders-4.9/WEExtensions.wox/WEExtensions.debug...done.
done.
Loaded symbols for /usr/lib64/GNUstep/WOxElemBuilders-4.9/WEExtensions.wox/./WEExtensions
0x00007fb32c98422b in _int_malloc () from /lib64/libc.so.6
Missing separate debuginfos, use: debuginfo-install cyrus-sasl-lib-2.1.23-13.el6_3.1.x86_64 glib2-2.22.5-7.el6.x86_64 glibc-2.12-1.107.el6_4.4.x86_64 keyutils-libs-1.4-4.el6.x86_64 krb5-libs-1.10.3-10.el6_4.4.x86_64 lasso-2.3.6-1.centos6.x86_64 libcom_err-1.41.12-14.el6_4.2.x86_64 libcurl-7.19.7-37.el6_4.x86_64 libffi-3.0.5-3.2.el6.x86_64 libgcc-4.4.7-3.el6.x86_64 libidn-1.18-2.el6.x86_64 libmemcached-0.49-1.x86_64 libobjc-4.4.7-3.el6.x86_64 libselinux-2.0.94-5.3.el6_4.1.x86_64 libssh2-1.4.2-1.el6.x86_64 libstdc++-4.4.7-3.el6.x86_64 libtool-ltdl-2.2.6-15.5.el6.x86_64 libxml2-2.7.6-12.el6_4.1.x86_64 libxslt-1.1.26-2.el6_3.1.x86_64 mysql-libs-5.1.69-1.el6_4.x86_64 nspr-4.9.5-2.el6_4.x86_64 nss-3.14.3-4.el6_4.x86_64 nss-softokn-freebl-3.14.3-3.el6_4.x86_64 nss-util-3.14.3-3.el6_4.x86_64 openldap-2.4.23-32.el6_4.1.x86_64 openssl-1.0.0-27.el6_4.2.x86_64 xmlsec1-1.2.16-2.el6.x86_64 xmlsec1-openssl-1.2.16-2.el6.x86_64 zlib-1.2.3-29.el6.x86_64
(gdb) bt
#0  0x00007fb32c98422b in _int_malloc () from /lib64/libc.so.6
#1  0x00007fb32c985951 in malloc () from /lib64/libc.so.6
#2  0x00007fb32e6d3534 in -[NGByteBuffer la:] (self=0x7fb3325f2fb8, _cmd=0x7fb32ee665b0, _la=1023) at NGByteBuffer.m:254
#3  0x00007fb32ebccbfb in _la (self=0x7fb33254b408, _la=1023) at NGMimePartParser.m:1306
#4  0x00007fb32ebcad56 in -[NGMimePartParser readBodyUnknownLengthStream] (self=0x7fb33254b408, _cmd=0x7fb32ee66420) at NGMimePartParser.m:861
#5  0x00007fb32ebcb2a9 in -[NGMimePartParser readBodyUnknownLength] (self=0x7fb33254b408, _cmd=0x7fb32ee66470) at NGMimePartParser.m:923
#6  0x00007fb32ebcba12 in -[NGMimePartParser readBody] (self=0x7fb33254b408, _cmd=0x7fb32ee66530) at NGMimePartParser.m:1041
#7  0x00007fb32ebcc12b in -[NGMimePartParser parseBodyOfPart:] (self=0x7fb33254b408, _cmd=0x7fb32f352d10, _part=0x7fb3325f00e8) at NGMimePartParser.m:1126
#8  0x00007fb32f02284b in -[NGHttpMessageParser parseBodyOfPart:] (self=0x7fb33254b408, _cmd=0x7fb32ee66620, _part=0x7fb3325f00e8) at NGHttpMessageParser.m:606
#9  0x00007fb32ebcc8d6 in -[NGMimePartParser parsePart] (self=0x7fb33254b408, _cmd=0x7fb32ee66660) at NGMimePartParser.m:1250
#10 0x00007fb32ebcc9d6 in -[NGMimePartParser parsePartFromStream:] (self=0x7fb33254b408, _cmd=0x7fb32f352d90, _stream=0x7fb3325a8518) at NGMimePartParser.m:1267
#11 0x00007fb32f022ed4 in -[NGHttpMessageParser parseResponseFromStream:] (self=0x7fb33254b408, _cmd=0x7fb32f339860, _stream=0x7fb3325a8518) at NGHttpMessageParser.m:713
#12 0x00007fb32f005916 in -[WOHTTPConnection readResponse] (self=0x7fb33254abe8, _cmd=0x7fb330373820) at WOHTTPConnection.m:542
#13 0x00007fb330114d14 in -[SOGoCASSession _performCASRequestWithAction:andParameters:] (self=0x7fb33253b618, _cmd=0x7fb3303738f0, casAction=0x7fb330372bc0, parameters=0x7fb331fe0298) at SOGoCASSession.m:398
#14 0x00007fb33011507c in -[SOGoCASSession _fetchTicketData] (self=0x7fb33253b618, _cmd=0x7fb330373920) at SOGoCASSession.m:436
#15 0x00007fb33011519b in -[SOGoCASSession login] (self=0x7fb33253b618, _cmd=0x7fb31fc51ec0) at SOGoCASSession.m:451
#16 0x00007fb31fa4a942 in -[SOGoRootPage _casDefaultAction] (self=0x7fb33251c7e8, _cmd=0x7fb31fc51fd0) at SOGoRootPage.m:330
#17 0x00007fb31fa4b4b7 in -[SOGoRootPage defaultAction] (self=0x7fb33251c7e8, _cmd=0x7fb32f3baa40) at SOGoRootPage.m:476
#18 0x00007fb32f088a98 in -[SoActionInvocation callOnObject:withPositionalParametersWhenNotNil:inContext:] (self=0x7fb332542f88, _cmd=0x7fb32f3baa60, _client=0x7fb3321d2d18, _positionalArgs=0x0, 
    _ctx=0x7fb33250b668) at SoActionInvocation.m:307
#19 0x00007fb32f088b6d in -[SoActionInvocation callOnObject:inContext:] (self=0x7fb332542f88, _cmd=0x7fb32f3b6f50, _client=0x7fb3321d2d18, _ctx=0x7fb33250b668) at SoActionInvocation.m:316
#20 0x00007fb32f082992 in -[SoObjectMethodDispatcher dispatchInContext:] (self=0x7fb33250b168, _cmd=0x7fb32f3b8650, _ctx=0x7fb33250b668) at SoObjectMethodDispatcher.m:191
#21 0x00007fb32f08511b in -[SoObjectRequestHandler handleRequest:inContext:session:application:] (self=0x7fb3321915f8, _cmd=0x7fb32f3402c0, _rq=0x7fb33258a5d8, _ctx=0x7fb33250b668, _sn=0x0, app=0x7fb3321d2d18)
    at SoObjectRequestHandler.m:584
#22 0x00007fb32f00cc44 in -[WORequestHandler handleRequest:] (self=0x7fb3321915f8, _cmd=0x7fb32f30b1c0, _request=0x7fb33258a5d8) at WORequestHandler.m:237
#23 0x00007fb32efc86dc in -[WOCoreApplication dispatchRequest:usingHandler:] (self=0x7fb3321d2d18, _cmd=0x7fb32f30b220, _request=0x7fb33258a5d8, handler=0x7fb3321915f8) at WOCoreApplication.m:712
#24 0x00007fb32efc8a38 in -[WOCoreApplication dispatchRequest:] (self=0x7fb3321d2d18, _cmd=0x7fb3307b3160, _request=0x7fb33258a5d8) at WOCoreApplication.m:752
#25 0x00007fb3305ab8a9 in -[SOGo dispatchRequest:] (self=0x7fb3321d2d18, _cmd=0x7fb32f3a1580, _request=0x7fb33258a5d8) at SOGo.m:453
#26 0x00007fb32f0721b9 in -[WOHttpTransaction _run] (self=0x7fb3325b6fc8, _cmd=0x7fb32f3a15b0) at WOHttpTransaction.m:592
#27 0x00007fb32f07258b in -[WOHttpTransaction run] (self=0x7fb3325b6fc8, _cmd=0x7fb32f39f320) at WOHttpTransaction.m:645
#28 0x00007fb32f06db0f in -[WOHttpAdaptor runConnection:] (self=0x7fb332260dd8, _cmd=0x7fb32f39f3c0, _socket=0x7fb33250d9b8) at WOHttpAdaptor.m:367
#29 0x00007fb32f06dd63 in -[WOHttpAdaptor _handleAcceptedConnection:] (self=0x7fb332260dd8, _cmd=0x7fb32f39f3d0, _connection=0x7fb33250d9b8) at WOHttpAdaptor.m:401
#30 0x00007fb32f06e1c8 in -[WOHttpAdaptor _handleConnection:] (self=0x7fb332260dd8, _cmd=0x7fb32f39f480, connection=0x7fb33250d9b8) at WOHttpAdaptor.m:460
#31 0x00007fb32f06e4e3 in -[WOHttpAdaptor acceptControlMessage:] (self=0x7fb332260dd8, _cmd=0x7fb32f39f1e0, aNotification=0x7fb332214e28) at WOHttpAdaptor.m:499
#32 0x00007fb32d7bde2f in -[NSNotificationCenter _postAndRelease:] (self=0x7fb331fc47e8, _cmd=0x7fb32dc79a50, notification=0x7fb332214e28) at NSNotificationCenter.m:1223
#33 0x00007fb32d7be152 in -[NSNotificationCenter postNotificationName:object:userInfo:] (self=0x7fb331fc47e8, _cmd=0x7fb32dc79a60, name=0x7fb32e682540, object=0x7fb3321d72e8, info=0x0)
    at NSNotificationCenter.m:1282
#34 0x00007fb32d7bdfe1 in -[NSNotificationCenter postNotificationName:object:] (self=0x7fb331fc47e8, _cmd=0x7fb32e682730, name=0x7fb32e682540, object=0x7fb3321d72e8) at NSNotificationCenter.m:1262
#35 0x00007fb32e43807a in -[NSObject(FileObjectWatcher) receivedEvent:type:extra:forMode:] (self=0x7fb3321d72e8, _cmd=0x7fb32dd005d0, _fdData=0x6, _type=ET_RDESC, _extra=0x6, _mode=0x7fb32dc9bfa0)
    at NSRunLoop+FileObjects.m:57
#36 0x00007fb32d8db635 in -[GSRunLoopCtxt pollUntil:within:] (self=0x7fb3321bd378, _cmd=0x7fb32dc9d160, milliseconds=11817, contexts=0x7fb332202998) at GSRunLoopCtxt.m:632
#37 0x00007fb32d80b78a in -[NSRunLoop acceptInputForMode:beforeDate:] (self=0x7fb332202218, _cmd=0x7fb32dc9d1a0, mode=0x7fb32dc9bfa0, limit_date=0x7fb332033698) at NSRunLoop.m:1198
#38 0x00007fb32d80bb99 in -[NSRunLoop runMode:beforeDate:] (self=0x7fb332202218, _cmd=0x7fb32f30b0b0, mode=0x7fb32dc9bfa0, date=0x7fb332033698) at NSRunLoop.m:1266
#39 0x00007fb32efc7e70 in -[WOCoreApplication run] (self=0x7fb3321d2d18, _cmd=0x7fb3307b2f80) at WOCoreApplication.m:584
#40 0x00007fb3305aaf1d in -[SOGo run] (self=0x7fb3321d2d18, _cmd=0x7fb32f348680) at SOGo.m:277
#41 0x00007fb32f016b91 in -[WOWatchDog _runChildWithControlSocket:] (self=0x7fb3322e8ed8, _cmd=0x7fb32f348730, controlSocket=0x7fb3321d72e8) at WOWatchDogApplicationMain.m:510
#42 0x00007fb32f01700d in -[WOWatchDog _spawnChild:] (self=0x7fb3322e8ed8, _cmd=0x7fb32f348800, child=0x7fb3321cd9c8) at WOWatchDogApplicationMain.m:578
#43 0x00007fb32f0177da in -[WOWatchDog _ensureChildren] (self=0x7fb3322e8ed8, _cmd=0x7fb32f3489d0) at WOWatchDogApplicationMain.m:668
#44 0x00007fb32f0189be in -[WOWatchDog run:argc:argv:] (self=0x7fb3322e8ed8, _cmd=0x7fb32f348ae0, newAppName=0x7fb3307b14c0, newArgC=7, newArgV=0x7fff514917c8) at WOWatchDogApplicationMain.m:919
#45 0x00007fb32f019211 in WOWatchDogApplicationMain (appName=0x7fb3307b14c0, argc=7, argv=0x7fff514917c8) at WOWatchDogApplicationMain.m:1033
#46 0x00007fb3305aa0ed in main (argc=7, argv=0x7fff514917c8, env=0x7fff51491808) at sogod.m:53
(gdb)
cas_bt.txt (23,750 bytes)   
jraby

jraby

2013-09-06 18:22

viewer   ~0005947

Thanks for the detailed bug report.

Can you get a pcap of the request from your cas server to /SOGo/casProxy (dump on 127.0.0.1:20000)
That way we'll know what reply SOGo sent back.

Also, it looks like sogo is blocked trying to read/parse the reply from the cas server. I'd really like to see the data that has been read up to the point where it hangs.

Can you reproduce the problem, attach to the hung sogod and do this:

bt (lookup the frame number for the [NGMimePartParser readBodyUnknownLengthStream] function call - with the current trace, it would be frame number 4 )
f 4 (go to the [NGMimePartParser readBodyUnknownLengthStream] frame)
p [body writeToFile:@"/tmp/casdata.txt" atomically:1]

This should write out the data to /tmp/casdata.txt.
If that doesn't work, simply print the data using: po body
and paste the result here.

If you're proficient with wireshark and ssldecrypting, having a decrypted pcap of the ssl request to /cas/serviceValidate would be really useful. (http://wiki.wireshark.org/SSL)

Thanks!

2013-09-07 10:01

 

cas_bt+po.txt (7,259 bytes)    
(gdb) bt
#0  0x00007f5d2bfab540 in -[NGByteBuffer la:] (self=0x7f5d306fc148, _cmd=0x7f5d2c73e5b0, _la=1023) at NGByteBuffer.m:256
#1  0x00007f5d2c4a4bfb in _la (self=0x7f5d306f81a8, _la=1023) at NGMimePartParser.m:1306
#2  0x00007f5d2c4a2d56 in -[NGMimePartParser readBodyUnknownLengthStream] (self=0x7f5d306f81a8, _cmd=0x7f5d2c73e420) at NGMimePartParser.m:861
#3  0x00007f5d2c4a32a9 in -[NGMimePartParser readBodyUnknownLength] (self=0x7f5d306f81a8, _cmd=0x7f5d2c73e470) at NGMimePartParser.m:923
#4  0x00007f5d2c4a3a12 in -[NGMimePartParser readBody] (self=0x7f5d306f81a8, _cmd=0x7f5d2c73e530) at NGMimePartParser.m:1041
#5  0x00007f5d2c4a412b in -[NGMimePartParser parseBodyOfPart:] (self=0x7f5d306f81a8, _cmd=0x7f5d2cc2ad10, _part=0x7f5d306f9b58) at NGMimePartParser.m:1126
#6  0x00007f5d2c8fa84b in -[NGHttpMessageParser parseBodyOfPart:] (self=0x7f5d306f81a8, _cmd=0x7f5d2c73e620, _part=0x7f5d306f9b58) at NGHttpMessageParser.m:606
#7  0x00007f5d2c4a48d6 in -[NGMimePartParser parsePart] (self=0x7f5d306f81a8, _cmd=0x7f5d2c73e660) at NGMimePartParser.m:1250
#8  0x00007f5d2c4a49d6 in -[NGMimePartParser parsePartFromStream:] (self=0x7f5d306f81a8, _cmd=0x7f5d2cc2ad90, _stream=0x7f5d306b29b8) at NGMimePartParser.m:1267
#9  0x00007f5d2c8faed4 in -[NGHttpMessageParser parseResponseFromStream:] (self=0x7f5d306f81a8, _cmd=0x7f5d2cc11860, _stream=0x7f5d306b29b8) at NGHttpMessageParser.m:713
#10 0x00007f5d2c8dd916 in -[WOHTTPConnection readResponse] (self=0x7f5d300cb158, _cmd=0x7f5d2dc4b820) at WOHTTPConnection.m:542
#11 0x00007f5d2d9ecd14 in -[SOGoCASSession _performCASRequestWithAction:andParameters:] (self=0x7f5d301212c8, _cmd=0x7f5d2dc4b8f0, casAction=0x7f5d2dc4abc0, parameters=0x7f5d30619238) at SOGoCASSession.m:398
#12 0x00007f5d2d9ed07c in -[SOGoCASSession _fetchTicketData] (self=0x7f5d301212c8, _cmd=0x7f5d2dc4b920) at SOGoCASSession.m:436
#13 0x00007f5d2d9ed19b in -[SOGoCASSession login] (self=0x7f5d301212c8, _cmd=0x7f5d1d529ec0) at SOGoCASSession.m:451
#14 0x00007f5d1d322942 in -[SOGoRootPage _casDefaultAction] (self=0x7f5d306a9de8, _cmd=0x7f5d1d529fd0) at SOGoRootPage.m:330
#15 0x00007f5d1d3234b7 in -[SOGoRootPage defaultAction] (self=0x7f5d306a9de8, _cmd=0x7f5d2cc92a40) at SOGoRootPage.m:476
#16 0x00007f5d2c960a98 in -[SoActionInvocation callOnObject:withPositionalParametersWhenNotNil:inContext:] (self=0x7f5d306513f8, _cmd=0x7f5d2cc92a60, _client=0x7f5d302dbd58, _positionalArgs=0x0,
    _ctx=0x7f5d30614418) at SoActionInvocation.m:307
#17 0x00007f5d2c960b6d in -[SoActionInvocation callOnObject:inContext:] (self=0x7f5d306513f8, _cmd=0x7f5d2cc8ef50, _client=0x7f5d302dbd58, _ctx=0x7f5d30614418) at SoActionInvocation.m:316
#18 0x00007f5d2c95a992 in -[SoObjectMethodDispatcher dispatchInContext:] (self=0x7f5d3063ee58, _cmd=0x7f5d2cc90650, _ctx=0x7f5d30614418) at SoObjectMethodDispatcher.m:191
#19 0x00007f5d2c95d11b in -[SoObjectRequestHandler handleRequest:inContext:session:application:] (self=0x7f5d302ad2b8, _cmd=0x7f5d2cc182c0, _rq=0x7f5d30693398, _ctx=0x7f5d30614418, _sn=0x0, app=0x7f5d302dbd58)
    at SoObjectRequestHandler.m:584
#20 0x00007f5d2c8e4c44 in -[WORequestHandler handleRequest:] (self=0x7f5d302ad2b8, _cmd=0x7f5d2cbe31c0, _request=0x7f5d30693398) at WORequestHandler.m:237
#21 0x00007f5d2c8a06dc in -[WOCoreApplication dispatchRequest:usingHandler:] (self=0x7f5d302dbd58, _cmd=0x7f5d2cbe3220, _request=0x7f5d30693398, handler=0x7f5d302ad2b8) at WOCoreApplication.m:712
#22 0x00007f5d2c8a0a38 in -[WOCoreApplication dispatchRequest:] (self=0x7f5d302dbd58, _cmd=0x7f5d2e08b160, _request=0x7f5d30693398) at WOCoreApplication.m:752
#23 0x00007f5d2de838a9 in -[SOGo dispatchRequest:] (self=0x7f5d302dbd58, _cmd=0x7f5d2cc79580, _request=0x7f5d30693398) at SOGo.m:453
#24 0x00007f5d2c94a1b9 in -[WOHttpTransaction _run] (self=0x7f5d306bfd88, _cmd=0x7f5d2cc795b0) at WOHttpTransaction.m:592
#25 0x00007f5d2c94a58b in -[WOHttpTransaction run] (self=0x7f5d306bfd88, _cmd=0x7f5d2cc77320) at WOHttpTransaction.m:645
#26 0x00007f5d2c945b0f in -[WOHttpAdaptor runConnection:] (self=0x7f5d30369c78, _cmd=0x7f5d2cc773c0, _socket=0x7f5d306158a8) at WOHttpAdaptor.m:367
#27 0x00007f5d2c945d63 in -[WOHttpAdaptor _handleAcceptedConnection:] (self=0x7f5d30369c78, _cmd=0x7f5d2cc773d0, _connection=0x7f5d306158a8) at WOHttpAdaptor.m:401
#28 0x00007f5d2c9461c8 in -[WOHttpAdaptor _handleConnection:] (self=0x7f5d30369c78, _cmd=0x7f5d2cc77480, connection=0x7f5d306158a8) at WOHttpAdaptor.m:460
#29 0x00007f5d2c9464e3 in -[WOHttpAdaptor acceptControlMessage:] (self=0x7f5d30369c78, _cmd=0x7f5d2cc771e0, aNotification=0x7f5d3037b698) at WOHttpAdaptor.m:499
#30 0x00007f5d2b095e2f in -[NSNotificationCenter _postAndRelease:] (self=0x7f5d300cd7e8, _cmd=0x7f5d2b551a50, notification=0x7f5d3037b698) at NSNotificationCenter.m:1223
#31 0x00007f5d2b096152 in -[NSNotificationCenter postNotificationName:object:userInfo:] (self=0x7f5d300cd7e8, _cmd=0x7f5d2b551a60, name=0x7f5d2bf5a540, object=0x7f5d3031ba48, info=0x0)
    at NSNotificationCenter.m:1282
#32 0x00007f5d2b095fe1 in -[NSNotificationCenter postNotificationName:object:] (self=0x7f5d300cd7e8, _cmd=0x7f5d2bf5a730, name=0x7f5d2bf5a540, object=0x7f5d3031ba48) at NSNotificationCenter.m:1262
#33 0x00007f5d2bd1007a in -[NSObject(FileObjectWatcher) receivedEvent:type:extra:forMode:] (self=0x7f5d3031ba48, _cmd=0x7f5d2b5d85d0, _fdData=0x6, _type=ET_RDESC, _extra=0x6, _mode=0x7f5d2b573fa0)
    at NSRunLoop+FileObjects.m:57
#34 0x00007f5d2b1b3635 in -[GSRunLoopCtxt pollUntil:within:] (self=0x7f5d302c63b8, _cmd=0x7f5d2b575160, milliseconds=22699, contexts=0x7f5d3030b9d8) at GSRunLoopCtxt.m:632
#35 0x00007f5d2b0e378a in -[NSRunLoop acceptInputForMode:beforeDate:] (self=0x7f5d3030b258, _cmd=0x7f5d2b5751a0, mode=0x7f5d2b573fa0, limit_date=0x7f5d302eb5b8) at NSRunLoop.m:1198
#36 0x00007f5d2b0e3b99 in -[NSRunLoop runMode:beforeDate:] (self=0x7f5d3030b258, _cmd=0x7f5d2cbe30b0, mode=0x7f5d2b573fa0, date=0x7f5d303a1a78) at NSRunLoop.m:1266
#37 0x00007f5d2c89fe70 in -[WOCoreApplication run] (self=0x7f5d302dbd58, _cmd=0x7f5d2e08af80) at WOCoreApplication.m:584
#38 0x00007f5d2de82f1d in -[SOGo run] (self=0x7f5d302dbd58, _cmd=0x7f5d2cc20680) at SOGo.m:277
#39 0x00007f5d2c8eeb91 in -[WOWatchDog _runChildWithControlSocket:] (self=0x7f5d303f1f38, _cmd=0x7f5d2cc20730, controlSocket=0x7f5d3031ba48) at WOWatchDogApplicationMain.m:510
#40 0x00007f5d2c8ef00d in -[WOWatchDog _spawnChild:] (self=0x7f5d303f1f38, _cmd=0x7f5d2cc20800, child=0x7f5d302d7e08) at WOWatchDogApplicationMain.m:578
#41 0x00007f5d2c8ef7da in -[WOWatchDog _ensureChildren] (self=0x7f5d303f1f38, _cmd=0x7f5d2cc209d0) at WOWatchDogApplicationMain.m:668
#42 0x00007f5d2c8f09be in -[WOWatchDog run:argc:argv:] (self=0x7f5d303f1f38, _cmd=0x7f5d2cc20ae0, newAppName=0x7f5d2e0894c0, newArgC=7, newArgV=0x7fff36972048) at WOWatchDogApplicationMain.m:919
#43 0x00007f5d2c8f1211 in WOWatchDogApplicationMain (appName=0x7f5d2e0894c0, argc=7, argv=0x7fff36972048) at WOWatchDogApplicationMain.m:1033
#44 0x00007f5d2de820ed in main (argc=7, argv=0x7fff36972048, env=0x7fff36972088) at sogod.m:53
(gdb) f 2
#2  0x00007f5d2c4a2d56 in -[NGMimePartParser readBodyUnknownLengthStream] (self=0x7f5d306f81a8, _cmd=0x7f5d2c73e420) at NGMimePartParser.m:861
861             _la(self, self->bufLen - 1);
(gdb) po body
<>
(gdb)
cas_bt+po.txt (7,259 bytes)   
dani

dani

2013-09-07 10:04

reporter   ~0005950

I tried several times to get the output you asked with gdb (either with p [body write etc... or with po body). Most of the times, I just get no result (the command doesn't return and just seems to hang). I just get the result I've attached once, where the po body only prints <> (see file cas_bt+po.txt)
Not sure if it's relevant.

2013-09-07 10:05

 

cas.xml (264 bytes)    
<cas:serviceResponse xmlns:cas='http://www.yale.edu/tp/cas'>
	<cas:authenticationSuccess>
		<cas:user>dani</cas:user>
		<cas:proxyGrantingTicket>PGTIOU-c221d770c5b1d7db4d5c5f8a082e466d</cas:proxyGrantingTicket>
	</cas:authenticationSuccess>
</cas:serviceResponse>
cas.xml (264 bytes)   
dani

dani

2013-09-07 10:07

reporter   ~0005951

I'm still trying to get wireshark SSL decrypting working. Waiting for this, after I triggered the issue, I manually ran:

wget -O cas.xml "https://auth.domain.tld/cas/serviceValidate?ticket=ST-57b955996295b3865cba3376e06cb522&amp;service=https%3A%2F%2Fwebmail.domain.tld%2FSOGo%2Fso%2Findex&amp;pgtUrl=https%3A%2F%2Fwebmail.domain.tld%2FSOGo%2FcasProxy&quot;

(the same requests SOGo sent to cas just before it hang). I've attached the result (which seems a valid cas response to me...)
jraby

jraby

2013-09-07 13:22

viewer   ~0005952

If body is empty, it means that sogod didn't get any data from the CAS server yet.
Can you get a pcap of the encrypted connection (would be better than nothing, but of course a decrypted one would be better)

From the sogo server, can you successfully connect to the CAS server?
something like: openssl s_client -connect auth.domain.tld:443
You'll need to specify -CAfile /path/to/ca-bundle.crt for it to validate the certificate correctly. Do you get any ssl error?
dani

dani

2013-09-07 13:36

reporter   ~0005953

openssl s_client can validate the certificate of my CAS server without an issue, even without specifying the CA (the CA which signed the CAS server cert is in /etc/pki/tls/certs, the default cert on CentOS, and I ran c_rehash on this dir to create the correct symlink).

I think the CAS server is sending the response, because I see in its log:

10.10.2.12 - - [07/Sep/2013:15:34:47 +0200] "GET /cas/serviceValidate?ticket=ST-a4cd3b040e2c1bc7abab1fb29dc12f5f&service=https%3A%2F%2Fwebmail.domain.tld%2FSOGo%2Fso%2Findex&pgtUrl=https%3A%2F%2Fwebmail.domain.tld%2FSOGo%2FcasProxy HTTP/1.1" 200 264 "-" "SOPE/4.9.37"

(so status code 200)

I'm still trying to decrypt the pcap file, will post when I get there
jraby

jraby

2013-09-07 13:56

viewer   ~0005954

can you post the pcap containing the encrypted connection?

2013-09-07 15:20

 

ssl.pcap (25,423 bytes)
dani

dani

2013-09-08 17:44

reporter   ~0005957

To debug this, I've configured everything to work with plain text HTTP (well, the only HTTPS used now is the CAS server calling the pgt URL as the URL sent by SOGo is hardcoded to use HTTPS). Some interesting things I've noted:

  • sogod doesn't hang anymore, but logs that it couldn't get a PGT (see sogo_http.log.txt), and alos logs <data>: not well formed 1

  • Still unable to auth, as the browser detects a redirection loop (auth against the CAS server, which redirects me to SOGo with the ticket, SOGo cannot obtain it's PGT, so redirects me to CAS etc...).

I'm also attaching the pcap of this. In this pcap:

  • 10.10.2.12 is the SOGo server
  • 10.10.1.10 is both my CAS server, and a reverse proxy (clients reach SOGo through a ProxyPass done by 10.10.1.10)

2013-09-08 17:44

 

sogod_http.log.txt (3,496 bytes)    
Sep 08 19:23:14 sogod [29042]: [WARN] <0x0x7f1125b98968[SOGoCASSession]> failure to obtain a PGT from the C.A.S. service
78.202.64.96, 10.10.1.10 - - [08/Sep/2013:19:23:14 GMT] "GET /SOGo/so/index?ticket=ST-ff4ee3f8f0d04c231aea3c6e8d2c3732 HTTP/1.1" 302 0/0 0.067 - - 8K
2013-09-08 19:23:15.346 sogod[29045] -[WEClientCapabilities initWithRequest:]: Unknown WebClient: user-agent='libwww-perl/5.833'
10.10.1.10 - - [08/Sep/2013:19:23:15 GMT] "GET /SOGo/casProxy?pgtIou=PGTIOU-b98b8e0a2642b67bef46df88879baf65&pgtId=PGT-7fd0d5a8e117c54bccc0b5013e951fca HTTP/1.1" 200 0/0 0.001 - - 0
2013-09-08 19:23:15.363 sogod[29042] <data>: not well formed 1
Sep 08 19:23:15 sogod [29042]: [WARN] <0x0x7f1125b47d48[SOGoCASSession]> failure to obtain a PGT from the C.A.S. service
78.202.64.96, 10.10.1.10 - - [08/Sep/2013:19:23:15 GMT] "GET /SOGo/so/index?ticket=ST-65c771d99cf0fcfe6e3c51f762ad9fd4 HTTP/1.1" 302 0/0 0.070 - - 4K
2013-09-08 19:23:15.758 sogod[29045] -[WEClientCapabilities initWithRequest:]: Unknown WebClient: user-agent='libwww-perl/5.833'
10.10.1.10 - - [08/Sep/2013:19:23:15 GMT] "GET /SOGo/casProxy?pgtIou=PGTIOU-2a197c85565fd066d326238c2ef5760d&pgtId=PGT-1fb40a652b35b952632165a7f6df0d93 HTTP/1.1" 200 0/0 0.001 - - 0
2013-09-08 19:23:15.774 sogod[29042] <data>: not well formed 1
Sep 08 19:23:15 sogod [29042]: [WARN] <0x0x7f1125badaa8[SOGoCASSession]> failure to obtain a PGT from the C.A.S. service
78.202.64.96, 10.10.1.10 - - [08/Sep/2013:19:23:15 GMT] "GET /SOGo/so/index?ticket=ST-30e08490d1deb900f447bc607fa7b649 HTTP/1.1" 302 0/0 0.067 - - 4K
2013-09-08 19:23:16.174 sogod[29045] -[WEClientCapabilities initWithRequest:]: Unknown WebClient: user-agent='libwww-perl/5.833'
10.10.1.10 - - [08/Sep/2013:19:23:16 GMT] "GET /SOGo/casProxy?pgtIou=PGTIOU-e838db8bf42cd51f485bb752eeb54d6e&pgtId=PGT-f966ae1649ec3532e02d5eed80e3c7e1 HTTP/1.1" 200 0/0 0.001 - - 0
2013-09-08 19:23:16.190 sogod[29042] <data>: not well formed 1
Sep 08 19:23:16 sogod [29042]: [WARN] <0x0x7f1125b47d48[SOGoCASSession]> failure to obtain a PGT from the C.A.S. service
78.202.64.96, 10.10.1.10 - - [08/Sep/2013:19:23:16 GMT] "GET /SOGo/so/index?ticket=ST-402b9ae05b05566fb35ba891d5bdcc91 HTTP/1.1" 302 0/0 0.068 - - 4K
2013-09-08 19:23:16.591 sogod[29045] -[WEClientCapabilities initWithRequest:]: Unknown WebClient: user-agent='libwww-perl/5.833'
10.10.1.10 - - [08/Sep/2013:19:23:16 GMT] "GET /SOGo/casProxy?pgtIou=PGTIOU-c1498c2257e7ea566136fc5e5696bd77&pgtId=PGT-da6a0629a69ba7a55b630ad1feb3bdce HTTP/1.1" 200 0/0 0.001 - - 0
2013-09-08 19:23:16.608 sogod[29042] <data>: not well formed 1
Sep 08 19:23:16 sogod [29042]: [WARN] <0x0x7f1125bb2bf8[SOGoCASSession]> failure to obtain a PGT from the C.A.S. service
78.202.64.96, 10.10.1.10 - - [08/Sep/2013:19:23:16 GMT] "GET /SOGo/so/index?ticket=ST-8898c0e0ba8c2d1c104f1e4070b43aac HTTP/1.1" 302 0/0 0.068 - - 8K
2013-09-08 19:23:17.001 sogod[29045] -[WEClientCapabilities initWithRequest:]: Unknown WebClient: user-agent='libwww-perl/5.833'
10.10.1.10 - - [08/Sep/2013:19:23:17 GMT] "GET /SOGo/casProxy?pgtIou=PGTIOU-ca96ca1b029740f181430bc82adf47be&pgtId=PGT-e102b660a3672ede3966b89bb3886011 HTTP/1.1" 200 0/0 0.001 - - 0
2013-09-08 19:23:17.017 sogod[29042] <data>: not well formed 1
Sep 08 19:23:17 sogod [29042]: [WARN] <0x0x7f1125b333e8[SOGoCASSession]> failure to obtain a PGT from the C.A.S. service
78.202.64.96, 10.10.1.10 - - [08/Sep/2013:19:23:17 GMT] "GET /SOGo/so/index?ticket=ST-672d3a18984f9516f2e1f0e5518f7a0c HTTP/1.1" 302 0/0 0.066 - - 4K
sogod_http.log.txt (3,496 bytes)   

2013-09-08 17:44

 

clear.pcap (98,245 bytes)
jraby

jraby

2013-09-12 14:57

viewer   ~0005980

Being unable to auth when using CAS over http is normal, it is by design.

I've looked at the encrypted ssl pcap and couldn't find anything unusual at first sight. Did you find a way to decrypt the ssl sessions?

Unfortunatly, since I'm unable to reproduce the issue here, I don't see how I could understand the problem without the pcap...
dani

dani

2013-09-15 15:53

reporter   ~0006001

Ok, I finally manage to decrypt my SSL pcap with wireshark (had to disable DH on apache). Unfortunatly, the "export SSL session keys" option doesn't seem to work, so I'll attach a new ssl.pcap, and both private keys needed to decrypt the data.

  • proxy.key is the private key of the CAS server (10.10.1.10)
  • webmail.key is the private key used by SOGo server (10.10.2.12)

2013-09-15 15:54

 

ssl2.pcap (23,971 bytes)

2013-09-15 15:54

 

proxy.key (1,704 bytes)

2013-09-15 15:54

 

webmail.key (1,704 bytes)
jraby

jraby

2013-09-16 17:45

viewer   ~0006005

Thanks for the pcap, I could decrypt them and see what's going on.

I have a gut feeling that SOPE is choking on the chunked data returned by CAS. Can you try adding the following parameters to your CAS server's apache config?

<pre>
BrowserMatch "SOPE/" downgrade-1.0
</pre>

This should force apache to consider SOPE's requests as HTTP/1.0, and will disable the use of the chunked encoding.

Let me know if that works for you.
dani

dani

2013-09-16 17:56

reporter   ~0006006

Already tried, and there's no difference (sogod still hangs, but I haven't captured it to check how data is sent from CAS to SOGo)
dani

dani

2013-09-16 18:03

reporter   ~0006007

Would having an access (login/pass) on such a CAS server can help ? (I can send you the info privatly)
jraby

jraby

2013-09-16 18:16

viewer   ~0006008

On the cas server, not really. On the sogo server, maybe, I could debug in gdb.

Can you post a pcap of the exchange with the 'downgrade-1.0' workaround in place?

2013-09-16 18:41

 

ssl_downgrade-1.0.pcap (18,066 bytes)
dani

dani

2013-09-16 18:42

reporter   ~0006009

I've just attached the pcap with a downgrade-1.0 added
jraby

jraby

2013-09-16 19:13

viewer   ~0006010

Last edited: 2013-09-16 19:13

This didn't do exactly what I wanted it to do:
<pre>
HTTP/1.1 200 OK
Date: Mon, 16 Sep 2013 18:31:44 GMT
Server: Apache/2.2.15 (CentOS)
Vary: Accept-Encoding,User-Agent
Connection: close
Content-Type: application/xml; charset=ISO-8859-1

<cas:serviceResponse xmlns:cas='http://www.yale.edu/tp/cas'>
.<cas:authenticationSuccess>
..<cas:user>REDACTED</cas:user>
..<cas:proxyGrantingTicket>PGTIOU-3a2998d252ab0f75398f35de702b4dc5</cas:proxyGrantingTicket>
.</cas:authenticationSuccess>
</cas:serviceResponse>
</pre>

There's no Content-Length header in there.
dani

dani

2013-09-17 07:29

reporter   ~0006011

Thx, adding something like this http://perl.apache.org/docs/2.0/user/handlers/filters.html#Setting_the_Content_Length_Header_in_Request_Output_Filters to force apache to add the Content-Length (and still using downgrade-1.0), SOGo interface is now accessible :)
I still have a small problem opening the IMAP connection, but not related to this issue.

As SOPE doesn't support chunked encoding, shouldn't it send HTTP 1.0 GET requests to CAS ?
jraby

jraby

2013-09-17 12:52

viewer   ~0006012

Great! nice find.

I'm not sure if SOPE doesn't support chunked encoding or if it just chokes on something.

As to sending out http 1.0 requests, that was my initial intent, but I wanted to make sure it worked before pushing a patch. I'll commit a simple patch in the next hours to workaround this issue.

Thanks for bringing up the issue and for the debugging help.
jraby

jraby

2013-09-17 13:11

viewer   ~0006013

Workaround here: https://github.com/inverse-inc/sogo/commit/60d6abe542cbed0bb4017edd404971b092627f36

Do you have a testing environment where you could test this patch if new nightly were available for your distro?
dani

dani

2013-09-17 13:26

reporter   ~0006015

Yes, I have two installations where I can test this as soon as nightlies are available (EL5 and EL6). I'll try tomorrow and will report
jraby

jraby

2013-09-17 14:05

viewer   ~0006017

New nightly builds are available for rhel5 & 6, 64bits.
dani

dani

2013-09-18 10:07

reporter   ~0006018

Just tried the nightly. SOGo is now sending HTTP/1.0 requests, so I don't need the downgrade-1.0 trick anymore. I still have to use a filter (http://perl.apache.org/docs/2.0/user/handlers/filters.html#Setting_the_Content_Length_Header_in_Request_Output_Filters) to have the Content-Length header added.

It's not very clear to me if the Content-Length is required when not using chunked encoding, so I don't know if the problem with Content-Length is on SOGo side or my CAS server side (LemonLDAP::NG).

Anyway, thanks for taking the time to look at this issue.
jraby

jraby

2013-09-18 13:21

viewer   ~0006020

Looks like the server is not required to send the content-length header along with its response if it closes the connection after sending it (section 7.2.2: http://www.w3.org/Protocols/HTTP/1.0/draft-ietf-http-spec.html#BodyLength)

We should fix this in SOPE, but I'm afraid we won't have time to work on this issue in the near future.

I'm closing this issue now since you have a good workaround, please reopen if you have other trouble relating to this.

Issue History

Date Modified Username Field Change
2013-09-06 06:45 dani New Issue
2013-09-06 06:45 dani File Added: cas_bt.txt
2013-09-06 18:22 jraby Note Added: 0005947
2013-09-06 18:22 jraby Status new => assigned
2013-09-06 18:22 jraby Assigned To => jraby
2013-09-07 10:01 dani File Added: cas_bt+po.txt
2013-09-07 10:04 dani Note Added: 0005950
2013-09-07 10:05 dani File Added: cas.xml
2013-09-07 10:07 dani Note Added: 0005951
2013-09-07 13:22 jraby Note Added: 0005952
2013-09-07 13:36 dani Note Added: 0005953
2013-09-07 13:56 jraby Note Added: 0005954
2013-09-07 15:20 dani File Added: ssl.pcap
2013-09-08 17:44 dani Note Added: 0005957
2013-09-08 17:44 dani File Added: sogod_http.log.txt
2013-09-08 17:44 dani File Added: clear.pcap
2013-09-12 14:57 jraby Note Added: 0005980
2013-09-15 15:53 dani Note Added: 0006001
2013-09-15 15:54 dani File Added: ssl2.pcap
2013-09-15 15:54 dani File Added: proxy.key
2013-09-15 15:54 dani File Added: webmail.key
2013-09-16 17:45 jraby Note Added: 0006005
2013-09-16 17:56 dani Note Added: 0006006
2013-09-16 18:03 dani Note Added: 0006007
2013-09-16 18:16 jraby Note Added: 0006008
2013-09-16 18:41 dani File Added: ssl_downgrade-1.0.pcap
2013-09-16 18:42 dani Note Added: 0006009
2013-09-16 19:13 jraby Note Added: 0006010
2013-09-16 19:13 jraby Note Edited: 0006010
2013-09-17 07:29 dani Note Added: 0006011
2013-09-17 12:52 jraby Note Added: 0006012
2013-09-17 13:11 jraby Note Added: 0006013
2013-09-17 13:26 dani Note Added: 0006015
2013-09-17 14:05 jraby Note Added: 0006017
2013-09-18 10:07 dani Note Added: 0006018
2013-09-18 13:21 jraby Note Added: 0006020
2013-09-18 13:21 jraby Status assigned => closed
2013-09-18 13:21 jraby Fixed in Version => 2.1.0