Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

deadlock while using hazmat #2911

Closed
alyukhan opened this issue May 12, 2016 · 5 comments
Closed

deadlock while using hazmat #2911

alyukhan opened this issue May 12, 2016 · 5 comments
Labels
backend bugs

Comments

@alyukhan
Copy link

alyukhan commented May 12, 2016 •
edited by alex

Deadlock is reproducible while using tornado https and requests. One thread is trying to perform handshake, acquires CRYPTO_LOCK_RSA lock and is trying to call to Cryptography_rand_bytes which required GIL. Another thread is keeping GIL and trying to execute PySSL_dealloc, which required locking of CRYPTO_LOCK_RSA.

Here is a repro:

import asyncio

import cryptography.hazmat.backends.openssl.backend
import requests
import tornado.platform.asyncio
import tornado.web
import tornado.httpserver


 # Will cause deadlock
cryptography.hazmat.backends.openssl.backend.activate_osrandom_engine()

 # Will fix deadlock
 #cryptography.hazmat.backends.openssl.backend.activate_builtin_random()

 # Port for local server
_PORT = 10001


 # local server
class Hello(tornado.web.RequestHandler):
    def get(self):
        self.write("hello")


application = tornado.web.Application([('/', Hello)])
http_server = tornado.httpserver.HTTPServer(application, ssl_options={
    "certfile": "/tmp/cert.pem"
})
tornado.platform.asyncio.AsyncIOMainLoop().install()
http_server.listen(_PORT)


@asyncio.coroutine
def tester():
    while True:
        yield from asyncio.get_event_loop().run_in_executor(
            None, lambda: requests.get(
                'https://127.0.0.1:{}'.format(_PORT), verify=False))


 # start stressing
for _ in range(11):
    asyncio.ensure_future(tester())

tornado.ioloop.IOLoop.instance().start()

Callstacks:

Thread #1
(gdb) bt
#0  0x00007f35b3828790 in sem_wait () from /lib64/libpthread.so.0
#1  0x000000000052d77e in PyThread_acquire_lock_timed (lock=0x113dcc0, microseconds=<optimized out>, intr_flag=0) at Python/thread_pthread.h:352
#2  0x00007f35aabb9d97 in CRYPTO_add_lock () from /lib64/libcrypto.so.10
#3  0x00007f35aac154d9 in RSA_free () from /lib64/libcrypto.so.10
#4  0x00007f35aac410db in EVP_PKEY_free_it () from /lib64/libcrypto.so.10
#5  0x00007f35aac41818 in EVP_PKEY_free () from /lib64/libcrypto.so.10
#6  0x00007f35aac50b60 in pubkey_cb () from /lib64/libcrypto.so.10
#7  0x00007f35aac5646a in asn1_item_combine_free () from /lib64/libcrypto.so.10
#8  0x00007f35aac566ff in ASN1_template_free () from /lib64/libcrypto.so.10
#9  0x00007f35aac5658a in asn1_item_combine_free () from /lib64/libcrypto.so.10
#10 0x00007f35aac566ff in ASN1_template_free () from /lib64/libcrypto.so.10
#11 0x00007f35aac5658a in asn1_item_combine_free () from /lib64/libcrypto.so.10
#12 0x00007f35aac56645 in ASN1_item_free () from /lib64/libcrypto.so.10
#13 0x00007f35aaf7ff48 in SSL_SESSION_free () from /lib64/libssl.so.10
#14 0x00007f35aaf7e2cd in SSL_free () from /lib64/libssl.so.10
#15 0x00007f35a8374a40 in PySSL_dealloc (self=0x7f35a4c6fb20) at /home/alyukhan/Python-3.4.4/Modules/_ssl.c:1481
#16 0x000000000045f44b in insertdict (mp=0x7f35a43c85c8, key=0x7f35a85fb810, hash=3968200442044068234, value=0x8496a0 <_Py_NoneStruct>) at Objects/dictobject.c:824

RSA_free call CRYPTO_add_lock on CRYPTO_LOCK_RSA
...
Thread #2
(gdb) bt
#0  0x00007f35b3826a82 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x00000000004dafdf in PyCOND_TIMEDWAIT (cond=0x897340 <gil_cond>, mut=0x897300 <gil_mutex>, us=5000) at Python/condvar.h:103
#2  take_gil (tstate=tstate@entry=0xef74e0) at Python/ceval_gil.h:224
#3  0x00000000004dbc39 in PyEval_RestoreThread (tstate=0xef74e0) at Python/ceval.c:448
#4  0x00007f35a6aba6d5 in gil_ensure () at c/misc_thread_common.h:104
#5  cffi_call_python (externpy=0x7f35a631a160 <_cffi_externpy__Cryptography_rand_status>, args=0x7ffdc9dacae0 "\340\365i\001") at c/call_python.c:234
#6  0x00007f35a607afb4 in Cryptography_rand_status () at build/temp.linux-x86_64-3.4/_openssl.c:12097
#7  0x00007f35aac1ab9e in RSA_setup_blinding () from /lib64/libcrypto.so.10
#8  0x00007f35aac128cc in rsa_get_blinding () from /lib64/libcrypto.so.10
#9  0x00007f35aac13c3c in RSA_eay_private_encrypt () from /lib64/libcrypto.so.10
#10 0x00007f35aac1596e in RSA_sign () from /lib64/libcrypto.so.10
#11 0x00007f35aac1a7dd in pkey_rsa_sign () from /lib64/libcrypto.so.10
#12 0x00007f35aac40d7e in EVP_SignFinal () from /lib64/libcrypto.so.10
#13 0x00007f35aaf57933 in ssl3_send_server_key_exchange () from /lib64/libssl.so.10
#14 0x00007f35aaf5b5d2 in ssl3_accept () from /lib64/libssl.so.10
#15 0x00007f35aaf690c8 in ssl23_accept () from /lib64/libssl.so.10
#16 0x00007f35a837a0a9 in PySSL_SSLdo_handshake (self=0x7f35a43d1fb8) at /home/alyukhan/Python-3.4.4/Modules/_ssl.c:570

Thread #2 obtained CRYPTO_LOCK_RSA at crypto/rsa/rsa_eay.c in rsa_get_blinding and making RSA_setup_blinding call under lock
@alex
Copy link
Member

alex commented May 29, 2016

Ugh. This sucks. Requires much thought.

@nlevitt
Copy link

nlevitt commented Sep 23, 2016

I've been hitting this bug in warcprox. Now I'll be working around it with cryptography.hazmat.backends.openssl.backend.activate_builtin_random(), so thanks @alyukhan for that. Very nice bug report too.

Thread 106 (Thread 0x7f1889510700 (LWP 10759)):
#0  0x00007f1891e747ce in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x000000000059ed0d in PyCOND_TIMEDWAIT (cond=0xaf4de0 <gil_cond>, mut=0xaf4e20 <gil_mutex>, us=5000) at ../Python/condvar.h:103
#2  0x000000000059f683 in take_gil (tstate=0x7f187c002e50) at ../Python/ceval_gil.h:224
#3  0x00000000005a0265 in PyEval_RestoreThread (tstate=0x7f187c002e50) at ../Python/ceval.c:448
#4  0x00007f188d8a8a3e in gil_ensure () at c/misc_thread_common.h:104
#5  0x00007f188d8c66d5 in cffi_call_python (externpy=0x7f188de21100 <_cffi_externpy__Cryptography_rand_status>, args=0x7f18894f5990 "\340b\005l\030\177")
    at c/call_python.c:234
#6  0x00007f188db152fa in Cryptography_rand_status () at build/temp.linux-x86_64-3.4-pydebug/_openssl.c:11784
#7  0x00007f188f3a859e in RSA_setup_blinding () from /lib/x86_64-linux-gnu/libcrypto.so.1.0.0
#8  0x00007f188f3a1854 in ?? () from /lib/x86_64-linux-gnu/libcrypto.so.1.0.0
#9  0x00007f188f3a29b0 in ?? () from /lib/x86_64-linux-gnu/libcrypto.so.1.0.0
#10 0x00007f188f3a3895 in RSA_sign () from /lib/x86_64-linux-gnu/libcrypto.so.1.0.0
#11 0x00007f188f3a83e5 in ?? () from /lib/x86_64-linux-gnu/libcrypto.so.1.0.0
#12 0x00007f188f3cc4f6 in EVP_SignFinal () from /lib/x86_64-linux-gnu/libcrypto.so.1.0.0
#13 0x00007f188e8fe25f in ?? () from /lib/x86_64-linux-gnu/libssl.so.1.0.0
#14 0x00007f188e901cca in ?? () from /lib/x86_64-linux-gnu/libssl.so.1.0.0
#15 0x00007f188e90f604 in ?? () from /lib/x86_64-linux-gnu/libssl.so.1.0.0
#16 0x00007f188eb51d25 in PySSL_SSLdo_handshake (self=0x7f18882e8658) at /build/python3.4-eNHHUi/python3.4-3.4.3/Modules/_ssl.c:570
#17 0x00000000005b81bf in call_function (pp_stack=0x7f18894f63b8, oparg=0) at ../Python/ceval.c:4220
...

Thread 58 (Thread 0x7f18347e0700 (LWP 10820)):
#0  0x00007f1891e76680 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x000000000043bc49 in PyThread_acquire_lock_timed (lock=0x1687390, microseconds=-1, intr_flag=0) at ../Python/thread_pthread.h:352
#2  0x000000000043bdd5 in PyThread_acquire_lock (lock=0x1687390, waitflag=1) at ../Python/thread_pthread.h:556
#3  0x00007f188eb5b89d in _ssl_thread_locking_function (mode=9, n=9, file=0x7f188f442d73 "rsa_lib.c", line=221)
    at /build/python3.4-eNHHUi/python3.4-3.4.3/Modules/_ssl.c:3829
#4  0x00007f188f339877 in CRYPTO_add_lock () from /lib/x86_64-linux-gnu/libcrypto.so.1.0.0
#5  0x00007f188f3a3469 in RSA_free () from /lib/x86_64-linux-gnu/libcrypto.so.1.0.0
#6  0x00007f188f3cc73b in ?? () from /lib/x86_64-linux-gnu/libcrypto.so.1.0.0
#7  0x00007f188f3cce38 in EVP_PKEY_free () from /lib/x86_64-linux-gnu/libcrypto.so.1.0.0
#8  0x00007f188f3db810 in ?? () from /lib/x86_64-linux-gnu/libcrypto.so.1.0.0
#9  0x00007f188f3e0f1a in ?? () from /lib/x86_64-linux-gnu/libcrypto.so.1.0.0
#10 0x00007f188f3e119f in ASN1_template_free () from /lib/x86_64-linux-gnu/libcrypto.so.1.0.0
#11 0x00007f188f3e103a in ?? () from /lib/x86_64-linux-gnu/libcrypto.so.1.0.0
#12 0x00007f188f3e119f in ASN1_template_free () from /lib/x86_64-linux-gnu/libcrypto.so.1.0.0
#13 0x00007f188f3e103a in ?? () from /lib/x86_64-linux-gnu/libcrypto.so.1.0.0
#14 0x00007f188f3e10f5 in ASN1_item_free () from /lib/x86_64-linux-gnu/libcrypto.so.1.0.0
#15 0x00007f188f3c0260 in sk_pop_free () from /lib/x86_64-linux-gnu/libcrypto.so.1.0.0
#16 0x00007f188e924f45 in ?? () from /lib/x86_64-linux-gnu/libssl.so.1.0.0
#17 0x00007f188e925b67 in SSL_SESSION_free () from /lib/x86_64-linux-gnu/libssl.so.1.0.0
#18 0x00007f188e923f5d in SSL_free () from /lib/x86_64-linux-gnu/libssl.so.1.0.0
#19 0x00007f188eb55878 in PySSL_dealloc (self=0x7f18881d06c0) at /build/python3.4-eNHHUi/python3.4-3.4.3/Modules/_ssl.c:1482
#20 0x00000000004cd67b in _Py_Dealloc (op=<_ssl._SSLSocket at remote 0x7f18881d06c0>) at ../Objects/object.c:1749
#21 0x00000000004b66bd in insertdict (mp=0x7f18881d1fa8, key='_sslobj', hash=-6554501129806641504, value=None) at ../Objects/dictobject.c:824
...

Here are the python traces for the same threads:

Thread 106 (Thread 0x7f1889510700 (LWP 10759)):
Traceback (most recent call first):
  Waiting for the GIL
  File "/usr/lib/python3.4/ssl.py", line 828, in do_handshake
    self._sslobj.do_handshake()
  File "/usr/lib/python3.4/ssl.py", line 601, in __init__
    self.do_handshake()
  File "/usr/lib/python3.4/ssl.py", line 911, in wrap_socket
    ciphers=ciphers)
  File "/1/brzl/warcprox-ve34/src/warcprox/warcprox/mitmproxy.py", line 245, in _transition_to_ssl
    server_side=True, certfile=self.server.ca.cert_for_host(self.hostname))
  File "/1/brzl/warcprox-ve34/src/warcprox/warcprox/mitmproxy.py", line 269, in do_CONNECT
    self._transition_to_ssl()
  File "/usr/lib/python3.4/http/server.py", line 386, in handle_one_request
    method()
  File "/usr/lib/python3.4/http/server.py", line 398, in handle
    self.handle_one_request()
  File "/usr/lib/python3.4/socketserver.py", line 673, in __init__
    self.handle()
  File "/1/brzl/warcprox-ve34/src/warcprox/warcprox/mitmproxy.py", line 182, in __init__
    http_server.BaseHTTPRequestHandler.__init__(self, request, client_address, server)
  File "/usr/lib/python3.4/socketserver.py", line 344, in finish_request
    self.RequestHandlerClass(request, client_address, self)
  File "/usr/lib/python3.4/socketserver.py", line 617, in process_request_thread
    self.finish_request(request, client_address)
  File "/usr/lib/python3.4/concurrent/futures/thread.py", line 54, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/lib/python3.4/concurrent/futures/thread.py", line 65, in _worker
    work_item.run()
  File "/usr/lib/python3.4/threading.py", line 868, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3.4/threading.py", line 920, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.4/threading.py", line 888, in _bootstrap
    self._bootstrap_inner()

Thread 58 (Thread 0x7f18347e0700 (LWP 10820)):
Traceback (most recent call first):
  File "/usr/lib/python3.4/ssl.py", line 818, in _real_close
    self._sslobj = None
  File "/usr/lib/python3.4/socket.py", line 252, in close
    self._real_close()
  File "/1/brzl/warcprox-ve34/src/warcprox/warcprox/mitmproxy.py", line 389, in _proxy_request
    self._remote_server_sock.close()
  File "/1/brzl/warcprox-ve34/src/warcprox/warcprox/warcproxy.py", line 219, in _proxy_request
    self)
  File "/1/brzl/warcprox-ve34/src/warcprox/warcprox/mitmproxy.py", line 324, in do_COMMAND
    self._proxy_request()
  File "/usr/lib/python3.4/http/server.py", line 386, in handle_one_request
    method()
  File "/1/brzl/warcprox-ve34/src/warcprox/warcprox/mitmproxy.py", line 283, in do_CONNECT
    self.handle_one_request()
  File "/usr/lib/python3.4/http/server.py", line 386, in handle_one_request
    method()
  File "/usr/lib/python3.4/http/server.py", line 398, in handle
    self.handle_one_request()
  File "/usr/lib/python3.4/socketserver.py", line 673, in __init__
    self.handle()
  File "/1/brzl/warcprox-ve34/src/warcprox/warcprox/mitmproxy.py", line 182, in __init__
    http_server.BaseHTTPRequestHandler.__init__(self, request, client_address, server)
  File "/usr/lib/python3.4/socketserver.py", line 344, in finish_request
    self.RequestHandlerClass(request, client_address, self)
  File "/usr/lib/python3.4/socketserver.py", line 617, in process_request_thread
    self.finish_request(request, client_address)
  File "/usr/lib/python3.4/concurrent/futures/thread.py", line 54, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/lib/python3.4/concurrent/futures/thread.py", line 65, in _worker
    work_item.run()
  File "/usr/lib/python3.4/threading.py", line 868, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3.4/threading.py", line 920, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.4/threading.py", line 888, in _bootstrap
    self._bootstrap_inner()

nlevitt added a commit to internetarchive/warcprox that referenced this issue Sep 23, 2016
@nlevitt
workaround for nasty python/ssl deadlock that has been affecting warc…
6000237 
…prox, same issue as pyca/cryptography#2911
@alex
Copy link
Member

alex commented Nov 22, 2016

Ok, these should both be fixed by our 1.6 release.

@alex alex closed this as completed Nov 22, 2016
melor added a commit to melor/pghoard that referenced this issue Jan 16, 2017
@melor
pghoard: workaround for cryptography deadlock bug
589d90d 
Workaround for random SSL-related hangs.

pyca/cryptography#2911
@melor melor mentioned this issue Jan 16, 2017
Merged
@vovanec
Copy link

vovanec commented Apr 11, 2019

I don't think it is fixed, neither 1.6 nor latest 2.6.1 version. I'm still seeing hang when running the test script provided in bug report.

@vovanec
Copy link

vovanec commented Apr 11, 2019 •
edited

And, suggested work around seems to be magically helping:

import cryptography.hazmat.backends.openssl.backend
cryptography.hazmat.backends.openssl.backend.activate_builtin_random()

@vovanec vovanec mentioned this issue Apr 11, 2019
Closed
@github-actions github-actions bot locked as resolved and limited conversation to collaborators Jul 29, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
backend bugs
Milestone
No milestone
Development

No branches or pull requests
4 participants
@alex @nlevitt @vovanec @alyukhan