Occasional failure of test_invalid_ntlm_creds due to timeout

[LHCGreg]

Not sure if this is indicative of a real problem or not, but I get occasional failure (maybe 50% of the time) of test_invalid_ntlm_creds due to a socket timeout. Debugging into it I found the timeout seemed to be 1.2 seconds which seems awfully short?

___________________________ test_invalid_ntlm_creds ___________________________

    def test_invalid_ntlm_creds():
        if not LIVE_TEST:
            pytest.skip('LIVE_TEST is not set')
        with pytest.raises(pytds.OperationalError):
>           pytds.connect(settings.HOST, auth=pytds.login.NtlmAuth(user_name='bad', password='bad'))

tests\connected_test.py:940:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
src\pytds\__init__.py:1326: in connect
    conn._open()
src\pytds\__init__.py:371: in _open
    self._try_open(timeout=retry_time)
src\pytds\__init__.py:353: in _try_open
    self._connect(host=host, port=port, instance=instance, timeout=timeout)
src\pytds\__init__.py:303: in _connect
    route = conn.login(login, sock, self._tzinfo_factory)
src\pytds\tds.py:1701: in login
    if not self._main_session.process_login_tokens():
src\pytds\tds.py:1497: in process_login_tokens
    marker = r.get_byte()
src\pytds\tds.py:170: in get_byte
    return self.unpack(_byte)[0]
src\pytds\tds.py:165: in unpack
    buf, offset = readall_fast(self, struc.size)
src\pytds\tds_base.py:575: in readall_fast
    buf, offset = stm.read_fast(size)
src\pytds\tds.py:145: in read_fast
    self._read_packet()
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <pytds.tds._TdsReader object at 0x0000021DBF1269E8>

    def _read_packet(self):
        """ Reads next TDS packet from the underlying transport

            If timeout is happened during reading of packet's header will
            cancel current request.
            Can only be called when transport's read pointer is at the begining
            of the packet.
            """
        try:
            pos = 0
            while pos < _header.size:
>               received = self._transport.recv_into(self._bufview[pos:_header.size-pos])
E               socket.timeout: timed out

src\pytds\tds.py:230: timeout
------------------------------ Captured log call ------------------------------
__init__.py                288 INFO     Opening socket to localhost:1433
tds.py                    1278 INFO     Sending PRELOGIN lib_ver=1090000 enc_flag=2 inst_name=b'MSSQLServer' mars=False
tds.py                    1322 INFO     Got PRELOGIN response crypt=2 mars=0
tds.py                    1411 INFO     Sending LOGIN tds_ver=74000004 bufsz=4096 pid=25548 opt1=f0 opt2=82 opt3=8 cli_tz=-240 cli_lcid=1033 cli_host=LAPTOP-6KQT7SUD lang= db=
tds.py                    1101 INFO     Sending CANCEL

[denisenkom]

I've never seen this one failing on my setup. What is your setup? Mac/windows/linux? SQL server on same machine or remote (high latency network)?

[denisenkom]

I usually run on Windows 10 with SQL server running on the same machine. Occasionally run on Mac.

[LHCGreg]

Windows 10, SQL Server running on the same machine. None of the other tests ever give me connection errors.

[LHCGreg]

I could not get it to happen today. It might only happen when on VPN. I'll test again next time I work from home.

[jwfergus]

I had it happen today on a dev spec'd azure DB. After the first timedout connection it worked fine. Not sure if anything should change for this, but on the first connection for a cold server this may be happening.

[dr-matthews]

This issue is happening intermittently for me and also seems to timeout after only about 1.2 seconds. The documentation says that the default login_timeout is 15 seconds. Could setting this explicitly improve things?

The SQL Server Logs show this when the error occurs:

The login packet used to open the connection is structurally invalid; the connection has been closed. Please contact the vendor of the client library. [CLIENT: x.x.x.x]

Here's the stack trace from my client app:

File "/opt/python/pytds/__init__.py", line 1352, in connect
    conn._open(sock=sock)
  File "/opt/python/pytds/__init__.py", line 379, in _open
    self._try_open(timeout=retry_time, sock=sock)
  File "/opt/python/pytds/__init__.py", line 361, in _try_open
    self._connect(host=host, port=port, instance=instance, timeout=timeout, sock=sock)
  File "/opt/python/pytds/__init__.py", line 304, in _connect
    route = conn.login(login, sock, self._tzinfo_factory)
  File "/opt/python/pytds/tds.py", line 1703, in login
    self._main_session.process_prelogin(login)
  File "/opt/python/pytds/tds.py", line 1290, in process_prelogin
    p = self._reader.read_whole_packet()
  File "/opt/python/pytds/tds.py", line 253, in read_whole_packet
    self._read_packet()
  File "/opt/python/pytds/tds.py", line 230, in _read_packet
    received = self._transport.recv_into(self._bufview[pos:], _header.size - pos)
socket.timeout: timed out

[denisenkom]

You are using old version, new version has a better retry mechanism, try upgrading