microsoft/mssql-django

10 minutes to close connection after an occurrence of 'query_timeout'.

aaronmader opened this issue · 3 comments

Software versions

  • Django: 5.0.4
  • mssql-django: 1.5
  • python: python:3.12.3-bookworm
  • SQL Server: unknown
  • OS: Debian 12.5 (bookworm)

Database Connection Settings

DATABASES = {
    'default': {
        'ENGINE': 'mssql',
        'NAME': os.environ.get('MSSQL_USER'),
        'USER': os.environ.get('MSSQL_USER'),
        'PASSWORD': os.environ.get('MSSQL_PASSWORD'),
        'HOST': os.environ.get('MSSQL_HOST'),
        'OPTIONS': {
            'query_timeout': 1,
        },
    },
}

Problem description and steps to reproduce
Setting the 'query_timeout' option works as expected. The exception is raised after the expected interval ('HYT00', '[HYT00] [Microsoft][ODBC Driver 17 for SQL Server]Query timeout expired (0) (SQLExecDirectW)'). However, when django attempts to close the connection (ex, when you close a django shell), those close operation takes 10 minutes.

To reproduce:

  • Set the the 'query_timeout' option in your settings, as above.
  • Open a django shell, and trigger an occurrence of the timeout.
  • Close the django shell, and notice the time required.
$ python manage.py shell
>>> from transaction.models import Transaction
>>> try:
>>>     # Trigger some slow query.
>>>     objects = list(Transaction.objects.all())
>>> except Exception as e:
>>>     if 'Query timeout expired' in str(e):
>>>         print("successfully triggered the query timeout!")
>>>     raise
>>> [ctrl-D]
now exiting InteractiveConsole...                      # <-- This hangs for 10 minutes??

Expected behavior and actual behavior
I expect the connection closing procedure to be quick, but it takes 10 minutes.

Can you provide an ODBC trace?

Here's the trace:
odbctrace.log

I did my best to isolate the trace to a single process's activity, but there's a bit of startup work caused by django's python manage.py shell

The issue can be see in the last ~30 lines of the trace log.
Namely:

  1. (at 1716383232.298629) The query_timeout is set to 1 second.
  2. (at 1716383232.298917) The slow query is requested.
  3. (at 1716383233.317473) The server returns the timeout response.
  4. (at 1716383235.890952) I press ctrl-d to close the shell. A 'disconnect' is sent.
  5. (at 1716383835.891218) The disconnect is successful (Notice that this is 10 minutes later)

Thanks,

Hi, the next release of the ODBC driver will contain the bug fix.