#302 OpenIDC provider seems to be unstable
Opened 7 months ago by bkabrda. Modified 6 months ago

Hi, I'm using Ipsilon as an OpenIDC provider, the account data is read from LDAP. I'm sometimes randomly logged out of my application and after looking in logs, I've discovered that Ipsilon sometimes randomly returns 500. I've managed to find 2 different errors in httpd logs of Ipsilon that seem to happen from time to time. I have no idea why they don't occur always, I just can't reproduce them consistently.

First error (seems to be quite frequent):

[Thu May 17 07:43:34.774227 2018] [:error] [pid 36] [17/May/2018:07:43:34] HTTP 
[Thu May 17 07:43:34.774244 2018] [:error] [pid 36] Request Headers:
[Thu May 17 07:43:34.774246 2018] [:error] [pid 36]   AUTHORIZATION: Bearer 3b1753aa-660d-4e42-a265-2884c266719f_IZwmSX3pqJVSx1XcxcckZHtf3lOLoSuu
[Thu May 17 07:43:34.774249 2018] [:error] [pid 36]   USER-AGENT: Python-httplib2/0.11.3 (gzip)
[Thu May 17 07:43:34.774251 2018] [:error] [pid 36]   Remote-Addr: 172.18.0.12
[Thu May 17 07:43:34.774253 2018] [:error] [pid 36]   HOST: localhost4.localdomain4:8443
[Thu May 17 07:43:34.774254 2018] [:error] [pid 36]   ACCEPT-ENCODING: gzip, deflate
[Thu May 17 07:43:34.774944 2018] [:error] [pid 36] [17/May/2018:07:43:34] HTTP Traceback (most recent call last):
[Thu May 17 07:43:34.774958 2018] [:error] [pid 36]   File "/usr/lib/python2.7/site-packages/cherrypy/_cprequest.py", line 656, in respond
[Thu May 17 07:43:34.774961 2018] [:error] [pid 36]     response.body = self.handler()
[Thu May 17 07:43:34.774963 2018] [:error] [pid 36]   File "/usr/lib/python2.7/site-packages/cherrypy/lib/encoding.py", line 188, in __call__
[Thu May 17 07:43:34.774965 2018] [:error] [pid 36]     self.body = self.oldhandler(*args, **kwargs)
[Thu May 17 07:43:34.774967 2018] [:error] [pid 36]   File "/usr/lib/python2.7/site-packages/cherrypy/_cpdispatch.py", line 34, in __call__
[Thu May 17 07:43:34.774969 2018] [:error] [pid 36]     return self.callable(*self.args, **self.kwargs)
[Thu May 17 07:43:34.774970 2018] [:error] [pid 36]   File "/usr/lib/python2.7/site-packages/ipsilon/util/page.py", line 91, in __call__
[Thu May 17 07:43:34.774972 2018] [:error] [pid 36]     return op(*args, **kwargs).encode('utf-8')
[Thu May 17 07:43:34.774974 2018] [:error] [pid 36]   File "/usr/lib/python2.7/site-packages/ipsilon/providers/common.py", line 114, in root
[Thu May 17 07:43:34.774976 2018] [:error] [pid 36]     return op(*args, **kwargs)
[Thu May 17 07:43:34.774977 2018] [:error] [pid 36]   File "/usr/lib/python2.7/site-packages/ipsilon/providers/openidc/api.py", line 361, in GET
[Thu May 17 07:43:34.774979 2018] [:error] [pid 36]     return self._get_userinfo(*kwargs, **kwargs)
[Thu May 17 07:43:34.774981 2018] [:error] [pid 36]   File "/usr/lib/python2.7/site-packages/ipsilon/providers/openidc/api.py", line 336, in _get_userinfo
[Thu May 17 07:43:34.774983 2018] [:error] [pid 36]     if self.api_client.get('userinfo_signed_response_alg'):
[Thu May 17 07:43:34.774985 2018] [:error] [pid 36] AttributeError: 'NoneType' object has no attribute 'get'

Second error (I've only seen this twice):

[Wed May 16 13:49:08.520306 2018] [:error] [pid 22] [16/May/2018:13:49:08]  ERROR: Failed to load data for table client for store OpenIDCStaticStore:[(ProgrammingError) column client.option does not exist
[Wed May 16 13:49:08.520337 2018] [:error] [pid 22] LINE 1: SELECT client.name, client.option, client.value 
[Wed May 16 13:49:08.520340 2018] [:error] [pid 22]                             ^
[Wed May 16 13:49:08.520342 2018] [:error] [pid 22]  'SELECT client.name, client.option, client.value \\nFROM client' {}]
[Wed May 16 13:49:08.527056 2018] [:error] [pid 22] 172.50.68.1 - - [16/May/2018:13:49:08] "GET /admin/providers/openidc/admin HTTP/1.1" 200 2905 "https://id.osci.redhat.com/admin/providers" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:60.0) Gecko/20100101 Firefox/60.0"
[Wed May 16 13:49:11.331636 2018] [:error] [pid 22] [16/May/2018:13:49:11]  ERROR: Failed to load data for table client for store OpenIDCStaticStore:[(ProgrammingError) column client.option does not exist
[Wed May 16 13:49:11.331655 2018] [:error] [pid 22] LINE 1: SELECT client.name, client.option, client.value 
[Wed May 16 13:49:11.331657 2018] [:error] [pid 22]                             ^
[Wed May 16 13:49:11.331659 2018] [:error] [pid 22]  'SELECT client.name, client.option, client.value \\nFROM client \\nWHERE client.name = %(name_1)s' {'name_1': '_cp_config'}]
[Wed May 16 13:49:11.382725 2018] [:error] [pid 22] 172.50.68.1 - - [16/May/2018:13:49:11] "GET /admin/providers/openidc/admin/client/D-627a14b6-fe9d-4091-9cac-26f355392c7b HTTP/1.1" 200 21284 "https://id.osci.redhat.com/admin/providers/openidc/admin" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:60.0) Gecko/20100101 Firefox/60.0"
[Wed May 16 13:49:32.493846 2018] [:error] [pid 22] [16/May/2018:13:49:32]  ERROR: Failed to load data for table client for store OpenIDCStaticStore:[(ProgrammingError) column client.option does not exist
[Wed May 16 13:49:32.493866 2018] [:error] [pid 22] LINE 1: SELECT client.name, client.option, client.value 
[Wed May 16 13:49:32.493868 2018] [:error] [pid 22]                             ^
[Wed May 16 13:49:32.493870 2018] [:error] [pid 22]  'SELECT client.name, client.option, client.value \\nFROM client' {}]

I'm running ipsilon-2.1.0-1.el7.centos.noarch inside a container in OpenShift and using it for authentication of Pagure users in my Pagure instance with flask-oidc.


After doing a lot of debugging, I think I managed to get to the root cause of the first traceback:

It seems that there's a race condition that involves ipsilon.providers.openidc.api:APIRequest._preop - if multiple requests come in a quick succession, _preop of one of the requests (called before every GET) sets self.api_client to None and before it can set it to the correct value, the other request gets to the part where it actually tries to access value stored in self.api_client, hence the Traceback is thrown. I'm unsure how to fix this ATM, but I'll try to figure this out.

It looks like I managed to solve this by storing the values on the request object instead of on self. Here's a patch that seems to be working for me: https://paste.fedoraproject.org/paste/vnrWTsi-ZCw75Uf8aKxtHg - does that make sense to you? Would you accept that as a PR? Thanks!

I see, so cherrypy reuses the same objects in the case of multiple threads.
Good digging, thanks you very much!
I would happily take that patch.

Metadata Update from @puiterwijk:
- Custom field component adjusted to None
- Custom field type adjusted to None
- Custom field version adjusted to None

6 months ago

Thanks, I'll send a PR.

Login to comment on this ticket.

Metadata