Bug 1274093 - ipsilon internal error on logout from SP
ipsilon internal error on logout from SP
Status: CLOSED WONTFIX
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: ipsilon (Show other bugs)
7.2
Unspecified Unspecified
unspecified Severity unspecified
: rc
: ---
Assigned To: Rob Crittenden
Namita Soman
: TestBlocker
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2015-10-21 18:00 EDT by Scott Poore
Modified: 2016-11-23 06:17 EST (History)
5 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2016-11-23 06:17:18 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
idp http logs (779.94 KB, application/x-gzip)
2015-10-22 09:48 EDT, Scott Poore
no flags Details
sp1 http logs (12.43 KB, application/x-gzip)
2015-10-22 09:49 EDT, Scott Poore
no flags Details
sp2 http logs (14.54 KB, application/x-gzip)
2015-10-22 09:49 EDT, Scott Poore
no flags Details

  None (edit)
Description Scott Poore 2015-10-21 18:00:25 EDT
Description of problem:

I'm seeing an internal error returned on logout from SP.

Environment is:

IPA server -> IDP -> SP{1,2}

Version-Release number of selected component (if applicable):

ipsilon-1.0.0-12.el7.noarch
sqlite-3.7.17-8.el7.x86_64

How reproducible:

Always

Steps to Reproduce:
1.  Install IPA Master and 3 clients

2.  On 1 client, install ipsilon and configure

yum -y install ipsilon ipsilon-infosssd ipsilon-saml2 ipsilon-authgssapi ipsilon-tools-ipa
kinit admin
ipsilon-server-install --ipa=yes --info-sssd=yes --form=yes
systemctl restart httpd
systemctl start certmonger
ipa-getcert request -f /etc/pki/tls/certs/server.pem \
    -k /etc/pki/tls/private/server.key \
    -K HTTP/`hostname`
vim /etc/httpd/conf.d/ssl.conf
...
SSLCertificateFile /etc/pki/tls/certs/server.pem
SSLCertificateKeyFile /etc/pki/tls/private/server.key
...
systemctl restart httpd


3. Configure SP{1,2} including web secure space with logout html

yum -y install ipsilon-client mod_ssl
ipsilon-client-install \
    --saml-idp-metadata https://idp.testrelm.test/idp/saml2/metadata \
    --saml-auth /secure
... 
cat /etc/httpd/saml2/`hostname`/metadata.xml
go to web browser at https://idp.testrelm.test/idp/ -> Administration ->
Identity Providers -> saml2 -> Manage -> Add New
Cut and paste Metadata.
...
kinit admin
ipa service-add HTTP/`hostname` --force
getcert stop-tracking -f /etc/pki/tls/certs/server.pem \
-k /etc/pki/tls/private/server.key
ipa-getcert request -f /etc/pki/tls/certs/server.pem \
    -k /etc/pki/tls/private/server.key \
    -K HTTP/`hostname`
vim /etc/httpd/conf.d/ssl.conf
...
SSLCertificateFile /etc/pki/tls/certs/server.pem
SSLCertificateKeyFile /etc/pki/tls/private/server.key
...
systemctl restart httpd
# Setup Web Server for SP:
mkdir -p /var/www/html/secure
hostname=$(hostname)
cat > /var/www/html/secure/index.html <<EOF
<html><title>Secure</title>Hello there...from $hostname ...<br>
<a href="/saml2/logout?ReturnTo=https://$hostname/logged_out.html">Log out</a>
<hr>
<!--#printenv -->
EOF
# Test Logout:
cat > /var/www/html/logged_out.html <<EOF
<html>
<title>Logout</title>
<p>
Congratulations, you've been logged out!
</p>
<p>
Now try to <a href="/secure/">log back in</a>
</p>
</html>
EOF
sed -i '/\/secure/a \    Options +Includes' /etc/httpd/conf.d/ipsilon-saml.conf
sed -i '/\/secure/a \    AddOutputFilter INCLUDES .html' /etc/httpd/conf.d/ipsilon-saml.conf
systemctl restart httpd


Actual results:

From another host with web browser, access SP1, then SP2.  Then select logout from SP2 and will see:


500 - Internal Server Error

Ipsilon encountered an unexpected internal error while trying to fulfill your request.

Please retry again.

If the error persists, contact the server administrator to resolve the problem.


Expected results:

logout without internal error

Additional info:

If I turn on debugging on IDP, I can see this in httpd error_log:

[Wed Oct 21 16:58:27.084176 2015] [:error] [pid 18947] [21/Oct/2015:16:58:27] HTTP Traceback (most recent call last):
[Wed Oct 21 16:58:27.084181 2015] [:error] [pid 18947]   File "/usr/lib/python2.7/site-packages/cherrypy/_cprequest.py", line 656, in respond
[Wed Oct 21 16:58:27.084183 2015] [:error] [pid 18947]     response.body = self.handler()
[Wed Oct 21 16:58:27.084185 2015] [:error] [pid 18947]   File "/usr/lib/python2.7/site-packages/cherrypy/lib/encoding.py", line 188, in __call__
[Wed Oct 21 16:58:27.084186 2015] [:error] [pid 18947]     self.body = self.oldhandler(*args, **kwargs)
[Wed Oct 21 16:58:27.084188 2015] [:error] [pid 18947]   File "/usr/lib/python2.7/site-packages/cherrypy/_cpdispatch.py", line 34, in __call__
[Wed Oct 21 16:58:27.084189 2015] [:error] [pid 18947]     return self.callable(*self.args, **self.kwargs)
[Wed Oct 21 16:58:27.084191 2015] [:error] [pid 18947]   File "/usr/lib/python2.7/site-packages/ipsilon/util/page.py", line 91, in __call__
[Wed Oct 21 16:58:27.084192 2015] [:error] [pid 18947]     return op(*args, **kwargs)
[Wed Oct 21 16:58:27.084194 2015] [:error] [pid 18947]   File "/usr/lib/python2.7/site-packages/ipsilon/providers/common.py", line 87, in root
[Wed Oct 21 16:58:27.084196 2015] [:error] [pid 18947]     return op(*args, **kwargs)
[Wed Oct 21 16:58:27.084197 2015] [:error] [pid 18947]   File "/usr/lib/python2.7/site-packages/ipsilon/providers/saml2idp.py", line 144, in GET
[Wed Oct 21 16:58:27.084199 2015] [:error] [pid 18947]     samlresponse=response)
[Wed Oct 21 16:58:27.084201 2015] [:error] [pid 18947]   File "/usr/lib/python2.7/site-packages/ipsilon/providers/saml2/logout.py", line 246, in logout
[Wed Oct 21 16:58:27.084202 2015] [:error] [pid 18947]     self.debug('Requesting logout for sessions %s' % indexes)
[Wed Oct 21 16:58:27.084203 2015] [:error] [pid 18947] TypeError: not all arguments converted during string formatting
[Wed Oct 21 16:58:27.084204 2015] [:error] [pid 18947] 
[Wed Oct 21 16:58:27.084220 2015] [:error] [pid 18947] ERROR:cherrypy.error.139666165767952:[21/Oct/2015:16:58:27] HTTP Traceback (most recent call last):
[Wed Oct 21 16:58:27.084222 2015] [:error] [pid 18947]   File "/usr/lib/python2.7/site-packages/cherrypy/_cprequest.py", line 656, in respond
[Wed Oct 21 16:58:27.084223 2015] [:error] [pid 18947]     response.body = self.handler()
[Wed Oct 21 16:58:27.084224 2015] [:error] [pid 18947]   File "/usr/lib/python2.7/site-packages/cherrypy/lib/encoding.py", line 188, in __call__
[Wed Oct 21 16:58:27.084225 2015] [:error] [pid 18947]     self.body = self.oldhandler(*args, **kwargs)
[Wed Oct 21 16:58:27.084226 2015] [:error] [pid 18947]   File "/usr/lib/python2.7/site-packages/cherrypy/_cpdispatch.py", line 34, in __call__
[Wed Oct 21 16:58:27.084228 2015] [:error] [pid 18947]     return self.callable(*self.args, **self.kwargs)
[Wed Oct 21 16:58:27.084230 2015] [:error] [pid 18947]   File "/usr/lib/python2.7/site-packages/ipsilon/util/page.py", line 91, in __call__
[Wed Oct 21 16:58:27.084231 2015] [:error] [pid 18947]     return op(*args, **kwargs)
[Wed Oct 21 16:58:27.084233 2015] [:error] [pid 18947]   File "/usr/lib/python2.7/site-packages/ipsilon/providers/common.py", line 87, in root
[Wed Oct 21 16:58:27.084234 2015] [:error] [pid 18947]     return op(*args, **kwargs)
[Wed Oct 21 16:58:27.084236 2015] [:error] [pid 18947]   File "/usr/lib/python2.7/site-packages/ipsilon/providers/saml2idp.py", line 144, in GET
[Wed Oct 21 16:58:27.084242 2015] [:error] [pid 18947]     samlresponse=response)
[Wed Oct 21 16:58:27.084244 2015] [:error] [pid 18947]   File "/usr/lib/python2.7/site-packages/ipsilon/providers/saml2/logout.py", line 246, in logout
[Wed Oct 21 16:58:27.084246 2015] [:error] [pid 18947]     self.debug('Requesting logout for sessions %s' % indexes)
[Wed Oct 21 16:58:27.084247 2015] [:error] [pid 18947] TypeError: not all arguments converted during string formatting
[Wed Oct 21 16:58:27.084248 2015] [:error] [pid 18947] 
[Wed Oct 21 16:58:27.084946 2015] [:error] [pid 18947] [21/Oct/2015:16:58:27]  DEBUG(ipsilon/util/errors.py:18 Errors.handler()): ['500 Internal Server Error', 'The server encountered an unexpected condition which prevented it from fulfilling the request.', 'Traceback (most recent call last):\\n  File "/usr/lib/python2.7/site-packages/cherrypy/_cprequest.py", line 656, in respond\\n    response.body = self.handler()\\n  File "/usr/lib/python2.7/site-packages/cherrypy/lib/encoding.py", line 188, in __call__\\n    self.body = self.oldhandler(*args, **kwargs)\\n  File "/usr/lib/python2.7/site-packages/cherrypy/_cpdispatch.py", line 34, in __call__\\n    return self.callable(*self.args, **self.kwargs)\\n  File "/usr/lib/python2.7/site-packages/ipsilon/util/page.py", line 91, in __call__\\n    return op(*args, **kwargs)\\n  File "/usr/lib/python2.7/site-packages/ipsilon/providers/common.py", line 87, in root\\n    return op(*args, **kwargs)\\n  File "/usr/lib/python2.7/site-packages/ipsilon/providers/saml2idp.py", line 144, in GET\\n    samlresponse=response)\\n  File "/usr/lib/python2.7/site-packages/ipsilon/providers/saml2/logout.py", line 246, in logout\\n    self.debug(\\'Requesting logout for sessions %s\\' % indexes)\\nTypeError: not all arguments converted during string formatting\\n', '3.2.2']
[Wed Oct 21 16:58:27.084970 2015] [:error] [pid 18947] INFO:cherrypy.error.139666165767952:[21/Oct/2015:16:58:27]  DEBUG(ipsilon/util/errors.py:18 Errors.handler()): ['500 Internal Server Error', 'The server encountered an unexpected condition which prevented it from fulfilling the request.', 'Traceback (most recent call last):\\n  File "/usr/lib/python2.7/site-packages/cherrypy/_cprequest.py", line 656, in respond\\n    response.body = self.handler()\\n  File "/usr/lib/python2.7/site-packages/cherrypy/lib/encoding.py", line 188, in __call__\\n    self.body = self.oldhandler(*args, **kwargs)\\n  File "/usr/lib/python2.7/site-packages/cherrypy/_cpdispatch.py", line 34, in __call__\\n    return self.callable(*self.args, **self.kwargs)\\n  File "/usr/lib/python2.7/site-packages/ipsilon/util/page.py", line 91, in __call__\\n    return op(*args, **kwargs)\\n  File "/usr/lib/python2.7/site-packages/ipsilon/providers/common.py", line 87, in root\\n    return op(*args, **kwargs)\\n  File "/usr/lib/python2.7/site-packages/ipsilon/providers/saml2idp.py", line 144, in GET\\n    samlresponse=response)\\n  File "/usr/lib/python2.7/site-packages/ipsilon/providers/saml2/logout.py", line 246, in logout\\n    self.debug(\\'Requesting logout for sessions %s\\' % indexes)\\nTypeError: not all arguments converted during string formatting\\n', '3.2.2']


Then a little later in log:

[Wed Oct 21 16:58:27.135610 2015] [:error] [pid 18947] INFO:cherrypy.error.139666165767952:[21/Oct/2015:16:58:27]  DEBUG(ipsilon/util/data.py:63 SqlStore.debug()): SqlStore cleanup: saml2.sessions.db.sqlite
[Wed Oct 21 16:58:27.135769 2015] [:error] [pid 18947] ERROR:sqlalchemy.pool.SingletonThreadPool:Exception during reset or similar
[Wed Oct 21 16:58:27.135776 2015] [:error] [pid 18947] Traceback (most recent call last):
[Wed Oct 21 16:58:27.135778 2015] [:error] [pid 18947]   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 567, in _finalize_fairy
[Wed Oct 21 16:58:27.135780 2015] [:error] [pid 18947]     fairy._reset(pool)
[Wed Oct 21 16:58:27.135781 2015] [:error] [pid 18947]   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 701, in _reset
[Wed Oct 21 16:58:27.135782 2015] [:error] [pid 18947]     pool._dialect.do_rollback(self)
[Wed Oct 21 16:58:27.135783 2015] [:error] [pid 18947]   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 406, in do_rollback
[Wed Oct 21 16:58:27.135785 2015] [:error] [pid 18947]     dbapi_connection.rollback()
[Wed Oct 21 16:58:27.135786 2015] [:error] [pid 18947] ProgrammingError: SQLite objects created in a thread can only be used in that same thread.The object was created in thread id 139665928148736 and this is thread id 139666250942208
[Wed Oct 21 16:58:27.135893 2015] [:error] [pid 18947] ERROR:sqlalchemy.pool.SingletonThreadPool:Exception closing connection <sqlite3.Connection object at 0x7f0684171bf8>
[Wed Oct 21 16:58:27.135897 2015] [:error] [pid 18947] Traceback (most recent call last):
[Wed Oct 21 16:58:27.135898 2015] [:error] [pid 18947]   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 250, in _close_connection
[Wed Oct 21 16:58:27.135909 2015] [:error] [pid 18947]     self._dialect.do_close(connection)
[Wed Oct 21 16:58:27.135910 2015] [:error] [pid 18947]   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 412, in do_close
[Wed Oct 21 16:58:27.135911 2015] [:error] [pid 18947]     dbapi_connection.close()
[Wed Oct 21 16:58:27.135913 2015] [:error] [pid 18947] ProgrammingError: SQLite objects created in a thread can only be used in that same thread.The object was created in thread id 139665928148736 and this is thread id 139666250942208
Comment 1 Scott Poore 2015-10-21 18:12:43 EDT
Marking this as a TestBlocker since it is a blocking from completely finishing multiple tests.
Comment 4 Scott Poore 2015-10-21 18:36:09 EDT
FYI, this is fixed with some other things from this ticket:

https://fedorahosted.org/ipsilon/ticket/59

Rob suggested to check if this would fix it:

change line 246 of /usr/lib/python2.7/site-packages/ipsilon/providers/saml2/logout.py on IDP and replace indexes with (indexes,)

Seems to.  I reset the browser tabs, logged out of everything and then back in.  First login to SP1, then SP2, then click logout for SP2.  This did not give internal error this time.

Thanks, Rob.
Comment 6 Scott Poore 2015-10-21 19:36:25 EDT
FYI, on IDP logout failure from comment #5, if I re-entered the url in location and selected logout again, it logged out as expected.
Comment 7 Scott Poore 2015-10-21 19:50:08 EDT
And, after uninstall and reinstall (just with commands, not of the software), I'm seeing an internal server error on SP2 after initial login from SP1.
Comment 8 Rob Crittenden 2015-10-21 20:03:22 EDT
The error log on the respective servers should have more information on what happened.
Comment 9 Scott Poore 2015-10-21 20:45:33 EDT
Oh course when I uninstalled and re-installed to gather clean logs, I also wiped the logs.  And now I can't reproduce it.  I'm not sure what the issue was.  The only thing I can think of is that maybe I didn't restart httpd on one of the hosts after changes or reinstall last time.  

Could that have resulted in such strange results?
Comment 10 Rob Crittenden 2015-10-22 08:42:04 EDT
Not restarting httpd after a re-install should make the SP not work at all as the metadata registered with the IdP will be different. I'm not sure what could have happened.
Comment 11 Scott Poore 2015-10-22 09:48:13 EDT
Ok, I was able to reproduce this again to get logs.  Hopefully that captured what you need.

Resinstall from scratch and installed SPs first using url method...I was unable to reproduce this morning using this method.

Reinstall again just the SPs using metadata method and was able to reproduce the initial error.

Then changed logout.py file to (indexes,) and tried reproducing again with no luck.

I logged out and logged back in, this time using kerberos.  And I was able to reproduce the issue.  login to SP1, confirm login on SP2, logout SP2 and see this error:
...
Internal Server Error

The server encountered an internal error or misconfiguration and was unable to complete your request.

Please contact the server administrator at root@localhost to inform them of the time this error occurred, and the actions you performed just before this error.

More information about this error may be available in the server error log.
...

And in location field for browser I see SP1 url:

https://rhel7-3.example.com/saml2/logout?SAMLRequest=hZJda4MwFIbv9ysk934kfodWmI2C0A22jl3spgRNV0ETl0Toz1%2FUDmph2%2BV5c56T9z3JRtG%2BG%2FBefIpRv7KvkSltXfqOKzyfbMEoORZUtQpz2jOFdY0Pj097jBwPD1JoUYsO3CB%2FE1QpJnUrOLAqsgXHXZoEaRqnEYwIiWGceygqyxymSV6SwCfAemdSmf4tMLiBlBpZxZWmXBvJg6ENPRuhN%2BjjwMO%2B9wEsYjK0nOqZOms9KOy68sy62PYddqH90DGnFr072UVuN2cH2WYq8XyBzNYYWmFtM1zRnmnaUE037i27DHo22StilUL2VP%2B%2BFOjAWWkb%2BzS34pGrgdXtqWUNsKYpLyPtplLep%2FnPFshOrBnNwuHV4OJpMTjgA1PTZivesEt2DApYwLIkKElQUIQwipF5Gz8Og6TYhV6%2BjLijHn7U1QfKvgE%3D&RelayState=https%3A%2F%2Frhel7-4.example.com%2Flogged_out.html&SigAlg=http%3A%2F%2Fwww.w3.org%2F2000%2F09%2Fxmldsig%23rsa-sha1&Signature=ODnNFeKVu0BxoIZTA8k9t0HlghnXAwf8XIphpwLOfk1FC5Xg0DT6kSHmilPwFkwdBAA7lBCLh2Jm87No3cGZrtQgp2HkCHvsHvBxwDlUyGllTVnCejyKZTU5rUnUtF28x740Fmhoyk2D%2FbRi%2BigC0W1K7ZjixkxX51GiYEDZe%2B5TY6%2FJHZd0w1dtIsOYYKKMxjSX9GEgRObLCk1H4ewYyCfqTj%2F8sHuQUE%2Bdp2OiC1%2FKSy5pG%2Fb9HQDAFpoF%2BTR%2FuFi%2FfX8HKVHzrFk0EXwWD0EyScwzfsLL3FYvcLP6XOfXu4ujwuhOe%2BQvZPHq3f4uU8KBv47IOWn5UMbzexYMwA%3D%3D

Thinking back to yesterday, I was probably running most of the tests where I saw these similar issues from a browser originally started with a user kerberos ticket.

I'll attach logs shortly.
Comment 12 Scott Poore 2015-10-22 09:48 EDT
Created attachment 1085559 [details]
idp http logs
Comment 13 Scott Poore 2015-10-22 09:49 EDT
Created attachment 1085560 [details]
sp1 http logs
Comment 14 Scott Poore 2015-10-22 09:49 EDT
Created attachment 1085561 [details]
sp2 http logs
Comment 16 Rob Crittenden 2015-10-30 10:18:21 EDT
The logout is failing due to an invalid signature on the logout request:

[Thu Oct 22 08:20:03.464935 2015] [:error] [pid 3318] [22/Oct/2015:08:20:03]  ERROR: Invalid SAML Request: <lasso.Samlp2LogoutRequest object at 0x7efe9c329510> (DsInvalidSignatureError() ['SAMLRequest=jZJd....'])

and then that invalid request isn't handled well within Ipsilon:

ERROR:cherrypy.error.139632007356112:[22/Oct/2015:08:20:03] HTTP Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/cherrypy/_cprequest.py", line 656, in respond
    response.body = self.handler()
  File "/usr/lib/python2.7/site-packages/cherrypy/lib/encoding.py", line 188, in __call__
    self.body = self.oldhandler(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/cherrypy/_cpdispatch.py", line 34, in __call__
    return self.callable(*self.args, **self.kwargs)
  File "/usr/lib/python2.7/site-packages/ipsilon/util/page.py", line 91, in __call__
    return op(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/ipsilon/providers/common.py", line 87, in root
    return op(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/ipsilon/providers/saml2idp.py", line 144, in GET
    samlresponse=response)
  File "/usr/lib/python2.7/site-packages/ipsilon/providers/saml2/logout.py", line 209, in logout
    self._handle_logout_request(us, logout, saml_sessions, message)
  File "/usr/lib/python2.7/site-packages/ipsilon/providers/saml2/logout.py", line 48, in _handle_logout_request
    raise InvalidRequest(msg)
InvalidRequest: "Invalid SAML Request: <lasso.Samlp2LogoutRequest object at 0x7efe9c329510> (DsInvalidSignatureError() ['SAMLRequest=jZJd...'])"
Comment 17 Rob Crittenden 2015-10-30 10:22:28 EDT
This handling was address upstream in https://fedorahosted.org/ipsilon/ticket/166 , git commit ee4d965a5d2329e9691059ddf08ab3a0a8f77330
Comment 19 Martin Kosek 2016-11-23 06:17:18 EST
Red Hat Enterprise Linux 7.2 introduced the Ipsilon identity provider service for federated single sign-on (SSO). Subsequently, Red Hat has released Red Hat Single Sign-On as a web SSO solution based on the Keycloak community project. Red Hat Single Sign-On provides greater capabilities than Ipsilon and is designated as the standard web SSO solution across the Red Hat product portfolio.

Therefore, as mentioned in the RHEL-7.3 Release Notes:
https://access.redhat.com/documentation/en-US/Red_Hat_Enterprise_Linux/7/html/7.3_Release_Notes/chap-Red_Hat_Enterprise_Linux-7.3_Release_Notes-Deprecated_Functionality.html
Ipsilon is now obsolete in RHEL and all existing Ipsilon users are recommended to migrate to Red Hat SSO product:
https://access.redhat.com/products/red-hat-single-sign-on
Please approach the Customer Service for advice.

Given above, this Bugzilla is now closed as WONTFIX.

Note You need to log in before you can comment on or make changes to this bug.