100% processor usage during GET have to wait 60s for response

When GET request have to wait 60s for remote service response, processor usage increases to 100% - version 1 of "requests" worked in this case better.
GET is configured with "cert" data and "timeout=120" over SSL connection.


Do you have a publicly-accessible URL that I can test against?


More details: GET is fired by sub-process (multiprocessing) - GET is calling API exposed by GSM operator - by this API I am receiving SMS and MMS. Other tasks fired by sub-proceses are using CPU below 1% (server with 2 Xeons).
I can expose on my server, over valid SSL, PHP script with 60s delay if this is what You mean?
Unfortunately I can not give You access to API exposed by GSM operator :( 


Hmm. In that case, can you show me your code? Feel free to remove identifying information (like URLs, header values etc.)


Here You are - direct call of requests.get from my library
(which is launched by multiprocessing.Process(target=launch_function,
args=('arg1', 'arg2')) ):

p_par = {
   'login': 'xxx',
   'password': 'xxx',
   'serviceId': '0000',
   'timeout': 60000, # wait 60s for response
   'deleteContent': 'true',
   'manualconfirm': 'true'
}

p_uri_part = 'getsms.aspx'

def __request_api2(self, p_par, p_uri_part=None):
   try:
      # GSM
      if self.__channel == '0':
         v_url = '{0}/{1}'.format(self.__API_0_URL, p_uri_part)
         v_crt = '{0}smsapi.crt'.format(self.__PATH_RES_SEC)
         v_key = '{0}smsapi.key'.format(self.__PATH_RES_SEC)
         try:
            v_rsp = requests.get(
               v_url, params=p_par
              ,cert=(v_crt, v_key)
              ,timeout=120

,verify='{0}ca_root_certificates.pem'.format(self.__PATH_RES_SEC)
            )
            v_res = v_rsp.text
         except Exception as e:
            self.__add_error('Error when invoking API: {0}'.format(str(e)))
            v_res = 0
   finally:
      return v_res

ca_root_certificates.pem - is grabbed from Mozilla - CA bundle

Best regards,
Artur


GitHub's email formatting made that pretty difficult to read, so I copy-pasted it into a code block here:

``` python
p_par = {
   'login': 'xxx',
   'password': 'xxx',
   'serviceId': '0000',
   'timeout': 60000, # wait 60s for response
   'deleteContent': 'true',
   'manualconfirm': 'true'
}

p_uri_part = 'getsms.aspx'

def __request_api2(self, p_par, p_uri_part=None):
   try:
      # GSM
      if self.__channel == '0':
         v_url = '{0}/{1}'.format(self.__API_0_URL, p_uri_part)
         v_crt = '{0}smsapi.crt'.format(self.__PATH_RES_SEC)
         v_key = '{0}smsapi.key'.format(self.__PATH_RES_SEC)
         try:
            v_rsp = requests.get(
               v_url, params=p_par
              ,cert=(v_crt, v_key)
              ,timeout=120
              ,verify='{0}ca_root_certificates.pem'.format(self.__PATH_RES_SEC)
            )
            v_res = v_rsp.text
         except Exception as e:
            self.__add_error('Error when invoking API: {0}'.format(str(e)))
            v_res = 0
   finally:
      return v_res
```


Hmm, there's nothing obviously wrong with that. When I get a moment I'll try to reproduce something similar on my machine.


I am in my phone, so I'll be brief. I suspect this is pyopenssl interacting with tje timeout. Especially the makefile function in urllib3.contrib.pyopenssl busylooping when no data is being recieved


Wait, does it do that? That's pretty awful.


This is a guess (I think I stumbled upon this previously). I'll check it later. Maybe gevent is also an issue. Gevent and pyopenssl don't really work together.


Hm, I can't reproduce this at the moment.

@e-manuel Could you give more information about your environment:
- Python version
- Operating System
- Using gevent? (or the like)
- Using pyOpenSSL?
- Does it work without multiprocessing?


- Python 2.7.6
- FreeBSD 9.0
- installed gevent 1.0 but in this case is not used
- I have installed py27- openssl-0.13
- my test: GET fired from python prompt work the same way (100% CPU after a few seconds) as sub-process fired from multiprocessing library


Do you also have `pyasn1` and `ndg-httpsclient` installed? (If they and `pyOpenSSL` are installed they trigger a different codepath)


Yes, I have: `py27-asn1-0.1.4_1,1`, `py27-ndg_httpsclient-0.3.2`, `py-openssl 0.13` but following the FreeBSD ports tree:
- `py27-asn1` is required by `py27-ndg_httpsclient`
- `py27-ndg_httpsclient` is required by `py-urllib3` (mentioned by @t-8ch) and requires to run: `py-openssl` and `py-asn1`
  Of course, I can de-install any of them, but I like to keep full functionality of requests (SSL, cert. etc.). What I should to do - "to be or not to be, this is the question..." ;)


So I managed to reproduce it:

Terminal 1:

``` sh
# netcat from the nmap project, should work with all ssl capable netcats
# We complete the SSL handshake but don't send a HTTP response line!
$ ncat --ssl -l 0.0.0.0 4000
```

Code:

``` python
request.get('https://127.0.0.1:4000', verify=False, timeout=120)
```

It seems this only happens when using PyOpenSSL, timeouts and FreeBSD.
I can't reproduce it any other way, permutating those conditions and on Linux.

@e-manuel Pick your poison :-)


Manually waiting for the buffer to be ready seems to fix it:

``` patch
diff --git a/requests/packages/urllib3/contrib/pyopenssl.py b/requests/packages/urllib3/contrib/pyopenssl.py
index d9bda15..67eeee4 100644
--- a/requests/packages/urllib3/contrib/pyopenssl.py
+++ b/requests/packages/urllib3/contrib/pyopenssl.py
@@ -156,6 +156,7 @@ class fileobject(_fileobject):
                 try:
                     data = self._sock.recv(rbufsize)
                 except OpenSSL.SSL.WantReadError:
+                    select.select([self._sock], [], [])
                     continue
                 if not data:
                     break
@@ -183,6 +184,7 @@ class fileobject(_fileobject):
                 try:
                     data = self._sock.recv(left)
                 except OpenSSL.SSL.WantReadError:
+                    select.select([self._sock], [], [])
                     continue
                 if not data:
                     break
@@ -234,6 +236,7 @@ class fileobject(_fileobject):
                                 break
                             buffers.append(data)
                     except OpenSSL.SSL.WantReadError:
+                        select.select([self._sock], [], [])
                         continue
                     break
                 return "".join(buffers)
@@ -244,6 +247,7 @@ class fileobject(_fileobject):
                 try:
                     data = self._sock.recv(self._rbufsize)
                 except OpenSSL.SSL.WantReadError:
+                    select.select([self._sock], [], [])
                     continue
                 if not data:
                     break
@@ -271,7 +275,8 @@ class fileobject(_fileobject):
                 try:
                     data = self._sock.recv(self._rbufsize)
                 except OpenSSL.SSL.WantReadError:
-                        continue
+                    select.select([self._sock], [], [])
+                    continue
                 if not data:
                     break
                 left = size - buf_len
```

(Insert lengthy rant about platform differences, especially concerning openssl here)


> (Insert lengthy rant about platform differences, especially concerning openssl here)

Yeah, platforms stink. Let's all develop on Windows. =P


I ranted about this to my housemate last night, by the by. I don't understand why PyOpenSSL busy-waits on this socket instead of calling select like a good person. @t-8ch are you making changes in the urllib3 version, or are you going to submit your patch upstream?


I would like to ask what next - there will be new release of requests ? I would not go back to pycurl :(


@e-manuel all of the changes are in PyOpenSSL. Since you're using the packages from your distro, you'll need to bother the maintainer of that package when it gets released.

@Lukasa your question is especially relevant since FreeBSD seems to strip out the vendored packages so it should be sent upstream if possible.


Yeah, I think we want an answer on what PyOpenSSL is going to do.

@e-manuel In the meantime, you can patch your copy so this stops happening.


@t-8ch thank You very much - Your patch works great, now when GET starts it uses below 2% of CPU and after few seconds less :)


Hurrah! Let's leave this open until we get an idea of what's happening upstream.

@t-8ch saves the day again! I should buy him a boat.


But you loose the timeouts I fear (althoug I'm not sure, if timeouts ever worked with pyopenssl).


Timeouts works now in this manner:
- when GETs target do not exists (is unreachable) timeout works like swiss quartz;
- when target exists, but not responds, GET waits forever.


Hmm. Can we pass the timeout to the select call?


Yep.
select.select([self._sock], [], [], self._sock.gettimeout())


@pasha-r That's a very neat solution, it didn't even occur to me. That, plus checking the return code from select, should add timeouts back. 


I think we should indeed go with our calling `select` ourself. PyOpenSSL does not have the timeout functionality and we simply set the timeout on the non ssl socket.

This should work:

``` patch
diff --git a/requests/packages/urllib3/contrib/pyopenssl.py b/requests/packages/urllib3/contrib/pyopenssl.py
index d9bda15..da44a29 100644
--- a/requests/packages/urllib3/contrib/pyopenssl.py
+++ b/requests/packages/urllib3/contrib/pyopenssl.py
@@ -43,7 +43,7 @@ from ndg.httpsclient.subj_alt_name import SubjectAltName as BaseSubjectAltName
 import OpenSSL.SSL
 from pyasn1.codec.der import decoder as der_decoder
 from pyasn1.type import univ, constraint
-from socket import _fileobject
+from socket import _fileobject, timeout
 import ssl
 import select
 from cStringIO import StringIO
@@ -139,6 +139,13 @@ def get_subj_alt_name(peer_cert):

 class fileobject(_fileobject):

+    def _wait_for_sock(self):
+        rd, wd, ed = select.select([self._sock], [], [],
+                                   self._sock.gettimeout())
+        if not rd:
+            raise timeout()
+
+
     def read(self, size=-1):
         # Use max, disallow tiny reads in a loop as they are very inefficient.
         # We never leave read() with any leftover data from a new recv() call
@@ -156,6 +163,7 @@ class fileobject(_fileobject):
                 try:
                     data = self._sock.recv(rbufsize)
                 except OpenSSL.SSL.WantReadError:
+                    self._wait_for_sock()
                     continue
                 if not data:
                     break
@@ -183,6 +191,7 @@ class fileobject(_fileobject):
                 try:
                     data = self._sock.recv(left)
                 except OpenSSL.SSL.WantReadError:
+                    self._wait_for_sock()
                     continue
                 if not data:
                     break
@@ -234,6 +243,7 @@ class fileobject(_fileobject):
                                 break
                             buffers.append(data)
                     except OpenSSL.SSL.WantReadError:
+                        self._wait_for_sock()
                         continue
                     break
                 return "".join(buffers)
@@ -244,6 +254,7 @@ class fileobject(_fileobject):
                 try:
                     data = self._sock.recv(self._rbufsize)
                 except OpenSSL.SSL.WantReadError:
+                    self._wait_for_sock()
                     continue
                 if not data:
                     break
@@ -271,7 +282,8 @@ class fileobject(_fileobject):
                 try:
                     data = self._sock.recv(self._rbufsize)
                 except OpenSSL.SSL.WantReadError:
-                        continue
+                    self._wait_for_sock()
+                    continue
                 if not data:
                     break
                 left = size - buf_len
```

The code seems suboptimal but I'd like to try keeping this close to the version from the stdlib (where 99% of the fileobject are taken from)

PS: It seems I was totally confused when not being able to reproduce this on Linux.
It is just the same there.


Suits me. =)


@t-8ch You are great - now timeout works fine in every case - and may CPUs can "sleep" calmly ;)