search

denisenkom / pytds

Python DBAPI driver for MSSQL using pure Python TDS (Tabular Data Stream) protocol implementation
MIT License
192 stars 53 forks source link

Azure SQL Datawarehouse OpenSSL.SSL.WantReadError #106

Closed thihara closed 4 years ago

thihara commented 5 years ago

We suddenly started receiving OpenSSL.SSL.WantReadError a few days back.

We didn't update our code.

Something must have changed in the Azure SQL Datawarehouse infrastructure.

This is the debug output and the error. The TLS handshake is failing.

2019-07-10 11:17:42,108 - pytds - INFO - Opening socket to testsslbug.database.windows.net:1433
2019-07-10 11:17:42,501 - root - INFO - Sending PRELOGIN lib_ver=1090000 enc_flag=1 inst_name=b'MSSQLServer' mars=False
2019-07-10 11:17:42,772 - root - INFO - Got PRELOGIN response crypt=1 mars=0
2019-07-10 11:17:42,773 - pytds.tls - INFO - doing TLS handshake
Traceback (most recent call last):
  File "/Users/thihara/workspace/python_virtual_environments/backend_aggregator/lib/python3.6/site-packages/pytds/tls.py", line 143, in establish_channel
    conn.do_handshake()
  File "/Users/thihara/workspace/python_virtual_environments/backend_aggregator/lib/python3.6/site-packages/OpenSSL/SSL.py", line 1915, in do_handshake
    self._raise_ssl_error(self._ssl, result)
  File "/Users/thihara/workspace/python_virtual_environments/backend_aggregator/lib/python3.6/site-packages/OpenSSL/SSL.py", line 1622, in _raise_ssl_error
    raise WantReadError()
OpenSSL.SSL.WantReadError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/thihara/workspace/backend_aggregator/datawarehouse/datawarehouse_test.py", line 31, in <module>
    cafile=settings.DB_CERT,
  File "/Users/thihara/workspace/python_virtual_environments/backend_aggregator/lib/python3.6/site-packages/pytds/__init__.py", line 1330, in connect
    conn._open()
  File "/Users/thihara/workspace/python_virtual_environments/backend_aggregator/lib/python3.6/site-packages/pytds/__init__.py", line 371, in _open
    self._try_open(timeout=retry_time)
  File "/Users/thihara/workspace/python_virtual_environments/backend_aggregator/lib/python3.6/site-packages/pytds/__init__.py", line 353, in _try_open
    self._connect(host=host, port=port, instance=instance, timeout=timeout)
  File "/Users/thihara/workspace/python_virtual_environments/backend_aggregator/lib/python3.6/site-packages/pytds/__init__.py", line 303, in _connect
    route = conn.login(login, sock, self._tzinfo_factory)
  File "/Users/thihara/workspace/python_virtual_environments/backend_aggregator/lib/python3.6/site-packages/pytds/tds.py", line 1703, in login
    self._main_session.process_prelogin(login)
  File "/Users/thihara/workspace/python_virtual_environments/backend_aggregator/lib/python3.6/site-packages/pytds/tds.py", line 1294, in process_prelogin
    self.parse_prelogin(octets=p, login=login)
  File "/Users/thihara/workspace/python_virtual_environments/backend_aggregator/lib/python3.6/site-packages/pytds/tds.py", line 1339, in parse_prelogin
    tls.establish_channel(self)
  File "/Users/thihara/workspace/python_virtual_environments/backend_aggregator/lib/python3.6/site-packages/pytds/tls.py", line 145, in establish_channel
    req = conn.bio_read(BUFSIZE)
  File "/Users/thihara/workspace/python_virtual_environments/backend_aggregator/lib/python3.6/site-packages/OpenSSL/SSL.py", line 1870, in bio_read
    self._handle_bio_errors(self._from_ssl, result)
  File "/Users/thihara/workspace/python_virtual_environments/backend_aggregator/lib/python3.6/site-packages/OpenSSL/SSL.py", line 1835, in _handle_bio_errors
    raise WantReadError()
OpenSSL.SSL.WantReadError

Process finished with exit code 1
thihara commented 5 years ago

@denisenkom

I should add the go-mssql is working perfectly fine.

We tested pyodbc and it seems to be working as well.

denisenkom commented 5 years ago

@thihara I added debugging output: https://github.com/denisenkom/pytds/commit/f647be63d8a946c0686897c058a979273676d00b Can you try with that and send me the resulting output?

eydelrivero commented 4 years ago

Hi @denisenkom ! I have the same problem as the OP. I tried with the new code and here is the debugging output. At the end, it raises again the same error OpenSSL.SSL.WantReadError

Opening socket to testdb.database.windows.net:1433
Sending PRELOGIN lib_ver=1090000 enc_flag=1 inst_name=b'MSSQLServer' mars=False
Got PRELOGIN response crypt=1 mars=0
doing TLS handshake
calling do_handshake
got WantReadError, getting data from the write end of the TLS connection buffer
sending 242 bytes of the handshake data to the server
receiving response from the server
adding 4088 bytes of the response into the TLS connection buffer
calling do_handshake
got WantReadError, getting data from the write end of the TLS connection buffer
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/pytds/tls.py", line 144, in establish_channel
    conn.do_handshake()
  File "/usr/local/lib/python3.7/site-packages/OpenSSL/SSL.py", line 1915, in do_handshake
    self._raise_ssl_error(self._ssl, result)
  File "/usr/local/lib/python3.7/site-packages/OpenSSL/SSL.py", line 1622, in _raise_ssl_error
    raise WantReadError()
OpenSSL.SSL.WantReadError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Volumes/D/repos/tests/deps/pytds_fetch.py", line 75, in <module>
    test_pytds_conn()
  File "/Volumes/D/repos/tests/deps/pytds_fetch.py", line 56, in test_pytds_conn
    tds_version=tds_base.TDS74) as conn:
  File "/usr/local/lib/python3.7/site-packages/pytds/__init__.py", line 1330, in connect
    conn._open()
  File "/usr/local/lib/python3.7/site-packages/pytds/__init__.py", line 371, in _open
    self._try_open(timeout=retry_time)
  File "/usr/local/lib/python3.7/site-packages/pytds/__init__.py", line 353, in _try_open
    self._connect(host=host, port=port, instance=instance, timeout=timeout)
  File "/usr/local/lib/python3.7/site-packages/pytds/__init__.py", line 303, in _connect
    route = conn.login(login, sock, self._tzinfo_factory)
  File "/usr/local/lib/python3.7/site-packages/pytds/tds.py", line 1703, in login
    self._main_session.process_prelogin(login)
  File "/usr/local/lib/python3.7/site-packages/pytds/tds.py", line 1294, in process_prelogin
    self.parse_prelogin(octets=p, login=login)
  File "/usr/local/lib/python3.7/site-packages/pytds/tds.py", line 1339, in parse_prelogin
    tls.establish_channel(self)
  File "/usr/local/lib/python3.7/site-packages/pytds/tls.py", line 147, in establish_channel
    req = conn.bio_read(BUFSIZE)
  File "/usr/local/lib/python3.7/site-packages/OpenSSL/SSL.py", line 1870, in bio_read
    self._handle_bio_errors(self._from_ssl, result)
  File "/usr/local/lib/python3.7/site-packages/OpenSSL/SSL.py", line 1835, in _handle_bio_errors
    raise WantReadError()
OpenSSL.SSL.WantReadError
tarper24 commented 4 years ago

@denisenkom I'm also getting this when trying to connect to Azure's Data Warehouse.

I'm willing to help debug it

denisenkom commented 4 years ago

Would you be able to capture Wireshark dump and send it to me together with logging output from the Python?

tarper24 commented 4 years ago

Sure! I'm away from my office for the next week, and can't access our Azure services, but I'll do that when I get back in!

On Fri, Dec 20, 2019 at 6:23 PM denisenkom notifications@github.com wrote:

Would you be able to capture Wireshark dump and send it to me together with logging output from the Python?

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/denisenkom/pytds/issues/106?email_source=notifications&email_token=AAY6LP3SOD2PZ3BAJUERDQLQZVOYVA5CNFSM4H7LYWIKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEHOQKVQ#issuecomment-568132950, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAY6LPYAKDNN267PPBAPQS3QZVOYVANCNFSM4H7LYWIA .

denisenkom commented 4 years ago

Also which version of pyOpenSSL do you use? If it is not the latest one, try upgrading it.

tarper24 commented 4 years ago

I uploaded the logs and Wireshark dump as a gist here: https://gist.github.com/tarper24/cc65bbcf57cf14ffd7af663bb7aa0f05

I used the latest pyOpenSSL: 19.1.0

tarper24 commented 4 years ago

@denisenkom After some messing around with the tls code some more, I was able to connect to Azure DW. Below is a diff with the change I made locally, along with the logs.

This is the code I changed that got it to work:

diff --git a/tls.py b/venv/Lib/site-packages/pytds/tls.py
index fcee6c7..1b9f464 100644
--- a/tls.py
+++ b/venv/Lib/site-packages/pytds/tls.py
@@ -147,13 +147,19 @@ def establish_channel(tds_sock):
             logger.debug(
                 "got WantReadError, getting data from the write end of the TLS connection buffer"
             )
-            req = conn.bio_read(BUFSIZE)
-            logger.debug(
-                "sending %d bytes of the handshake data to the server", len(req)
-            )
-            w.begin_packet(tds_base.PacketType.PRELOGIN)
-            w.write(req)
-            w.flush()
+
+            try:
+                req = conn.bio_read(BUFSIZE)
+            except OpenSSL.SSL.WantReadError:
+                logger.debug("got WantReadError again...")
+            else:
+                logger.debug(
+                    "sending %d bytes of the handshake data to the server", len(req)
+                )
+                w.begin_packet(tds_base.PacketType.PRELOGIN)
+                w.write(req)
+                w.flush()
+
             logger.debug("receiving response from the server")
             resp = r.read_whole_packet()
             # TODO validate r.packet_type

I just told it to ignore the subsequent WantReadError if it happened.

Here are the logs:

INFO:pytds:Opening socket to azure-dw.database.windows.net:1433
INFO:root:Sending PRELOGIN lib_ver=1090000 enc_flag=1 inst_name=b'MSSQLServer' mars=False
INFO:root:Got PRELOGIN response crypt=1 mars=0
INFO:pytds.tls:doing TLS handshake
DEBUG:pytds.tls:calling do_handshake
DEBUG:pytds.tls:got WantReadError, getting data from the write end of the TLS connection buffer
DEBUG:pytds.tls:sending 246 bytes of the handshake data to the server
DEBUG:pytds.tls:receiving response from the server
DEBUG:pytds.tls:adding 4088 bytes of the response into the TLS connection buffer
DEBUG:pytds.tls:calling do_handshake
DEBUG:pytds.tls:got WantReadError, getting data from the write end of the TLS connection buffer
DEBUG:pytds.tls:got WantReadError again...
DEBUG:pytds.tls:receiving response from the server
DEBUG:pytds.tls:adding 382 bytes of the response into the TLS connection buffer
DEBUG:pytds.tls:calling do_handshake
DEBUG:pytds.tls:got WantReadError, getting data from the write end of the TLS connection buffer
DEBUG:pytds.tls:sending 126 bytes of the handshake data to the server
DEBUG:pytds.tls:receiving response from the server
DEBUG:pytds.tls:adding 51 bytes of the response into the TLS connection buffer
DEBUG:pytds.tls:calling do_handshake
INFO:pytds.tls:TLS handshake is complete
INFO:root:Sending LOGIN tds_ver=74000004 bufsz=4096 pid=17036 opt1=f0 opt2=2 opt3=8 cli_tz=-360 cli_lcid=1033 cli_host=IT-WS337 lang= db=dw-db
INFO:root:switched to database dw-db
INFO:root:switched collation to Collation(lcid=1033, sort_id=0, ignore_case=True, ignore_accent=False, ignore_width=False, ignore_kana=False, binary=False, binary2=False, version=8)
INFO:root:switched language to us_english
INFO:root:Got LOGINACK tds_ver=74000004 srv_name=Microsoft SQL Server   srv_ver=c0009e3
INFO:root:Sending BEGIN TRAN il=0
INFO:root:Sending query SELECT GETDATE()
(datetime.datetime(2020, 1, 3, 17, 13, 20, 710000),)

It looks like it just gets that bad WantReadError once, and when ignored it succeeds.

denisenkom commented 4 years ago

Can you raise a PR with your change? Also in the exception handler can you add a comment referencing this issue: https://github.com/pyca/pyopenssl/issues/887?

tarper24 commented 4 years ago

@denisenkom sorry for the wait! I made the PR here: https://github.com/denisenkom/pytds/pull/110