DatabaseOperations.format_debug_sql() crashes when query fails to execute on some backends

[Jacob Walls]

With django-docker-box,

docker compose run --rm oracle backends --debug-sql

Gives two new failures bisected to d8f093908c504ae0dbc39d3f5231f7d7920dde37. (The third failure you get when running this command is omitted since it's pre-existing and reproducible on all databases, so it's not relevant here.)

This is also distinct from the failure currently showing on the oracle runner on main.

===============
ERROR: test_outer_wrapper_blocks (backends.base.test_base.ExecuteWrapperTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/django/source/tests/backends/base/test_base.py", line 192, in test_outer_wrapper_blocks
    cursor.execute("The database never sees this")
  File "/django/source/django/db/backends/utils.py", line 121, in execute
    with self.debug_sql(sql, params, use_last_executed_query=True):
  File "/usr/local/lib/python3.10/contextlib.py", line 142, in __exit__
    next(self.gen)
  File "/django/source/django/db/backends/utils.py", line 154, in debug_sql
    self.db.ops.format_debug_sql(sql),
  File "/django/source/django/db/backends/base/operations.py", line 791, in format_debug_sql
    return sqlparse.format(sql, reindent=True, keyword_case="upper")
  File "/usr/local/lib/python3.10/site-packages/sqlparse/__init__.py", line 59, in format
    return ''.join(stack.run(sql, encoding))
  File "/usr/local/lib/python3.10/site-packages/sqlparse/engine/filter_stack.py", line 39, in run
    for stmt in stream:
  File "/usr/local/lib/python3.10/site-packages/sqlparse/engine/statement_splitter.py", line 87, in process
    for ttype, value in stream:
  File "/usr/local/lib/python3.10/site-packages/sqlparse/filters/tokens.py", line 19, in process
    for ttype, value in stream:
  File "/usr/local/lib/python3.10/site-packages/sqlparse/lexer.py", line 134, in get_tokens
    raise TypeError("Expected text or file-like object, got {!r}".
TypeError: Expected text or file-like object, got <class 'NoneType'>

----------------------------------------------------------------------

======================================================================
ERROR: test_cursor_contextmanager (backends.tests.BackendTestCase)
Cursors can be used as a context manager
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/django/source/django/db/backends/utils.py", line 103, in _execute
    return self.cursor.execute(sql)
  File "/django/source/django/db/backends/oracle/base.py", line 627, in execute
    return self.cursor.execute(query, self._param_generator(params))
  File "/usr/local/lib/python3.10/site-packages/oracledb/cursor.py", line 708, in execute
    self._prepare_for_execute(statement, parameters, keyword_parameters)
  File "/usr/local/lib/python3.10/site-packages/oracledb/cursor.py", line 136, in _prepare_for_execute
    self._verify_open()
  File "/usr/local/lib/python3.10/site-packages/oracledb/cursor.py", line 155, in _verify_open
    errors._raise_err(errors.ERR_CURSOR_NOT_OPEN)
  File "/usr/local/lib/python3.10/site-packages/oracledb/errors.py", line 195, in _raise_err
    raise error.exc_type(error) from cause
oracledb.exceptions.InterfaceError: DPY-1006: cursor is not open

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/django/source/django/db/backends/utils.py", line 134, in debug_sql
    yield
  File "/django/source/django/db/backends/utils.py", line 122, in execute
    return super().execute(sql, params)
  File "/django/source/django/db/backends/utils.py", line 79, in execute
    return self._execute_with_wrappers(
  File "/django/source/django/db/backends/utils.py", line 92, in _execute_with_wrappers
    return executor(sql, params, many, context)
  File "/django/source/django/db/backends/utils.py", line 100, in _execute
    with self.db.wrap_database_errors:
  File "/django/source/django/db/utils.py", line 91, in __exit__
    raise dj_exc_value.with_traceback(traceback) from exc_value
  File "/django/source/django/db/backends/utils.py", line 103, in _execute
    return self.cursor.execute(sql)
  File "/django/source/django/db/backends/oracle/base.py", line 627, in execute
    return self.cursor.execute(query, self._param_generator(params))
  File "/usr/local/lib/python3.10/site-packages/oracledb/cursor.py", line 708, in execute
    self._prepare_for_execute(statement, parameters, keyword_parameters)
  File "/usr/local/lib/python3.10/site-packages/oracledb/cursor.py", line 136, in _prepare_for_execute
    self._verify_open()
  File "/usr/local/lib/python3.10/site-packages/oracledb/cursor.py", line 155, in _verify_open
    errors._raise_err(errors.ERR_CURSOR_NOT_OPEN)
  File "/usr/local/lib/python3.10/site-packages/oracledb/errors.py", line 195, in _raise_err
    raise error.exc_type(error) from cause
django.db.utils.InterfaceError: DPY-1006: cursor is not open

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/django/source/tests/backends/tests.py", line 466, in test_cursor_contextmanager
    cursor.execute("SELECT 1" + connection.features.bare_select_suffix)
  File "/django/source/django/db/backends/utils.py", line 121, in execute
    with self.debug_sql(sql, params, use_last_executed_query=True):
  File "/usr/local/lib/python3.10/contextlib.py", line 153, in __exit__
    self.gen.throw(typ, value, traceback)
  File "/django/source/django/db/backends/utils.py", line 154, in debug_sql
    self.db.ops.format_debug_sql(sql),
  File "/django/source/django/db/backends/base/operations.py", line 791, in format_debug_sql
    return sqlparse.format(sql, reindent=True, keyword_case="upper")
  File "/usr/local/lib/python3.10/site-packages/sqlparse/__init__.py", line 59, in format
    return ''.join(stack.run(sql, encoding))
  File "/usr/local/lib/python3.10/site-packages/sqlparse/engine/filter_stack.py", line 39, in run
    for stmt in stream:
  File "/usr/local/lib/python3.10/site-packages/sqlparse/engine/statement_splitter.py", line 87, in process
    for ttype, value in stream:
  File "/usr/local/lib/python3.10/site-packages/sqlparse/filters/tokens.py", line 19, in process
    for ttype, value in stream:
  File "/usr/local/lib/python3.10/site-packages/sqlparse/lexer.py", line 134, in get_tokens
    raise TypeError("Expected text or file-like object, got {!r}".
TypeError: Expected text or file-like object, got <class 'NoneType'>

----------------------------------------------------------------------

[Tim Graham]

I'll look into it (unless you do so in the meantime).

[Jacob Walls]

Terrific, thanks.

[Sarah Boyce]

Fixed in ec8cbea91ed6362d43298caa43f3d868452f7efa
See ​https://djangoci.com/job/django-oracle/

[Sarah Boyce]

Apologies I misunderstood - confirmed tests are failing as reported

[Tim Graham]

This happens on any database backend where DatabaseOperations.last_executed_query() can return None (i.e. the query failed) For example, I observed the same failure ​on PostgreSQL.

I think there should either be a guard so that a failed query (sql=None) isn't ​logged in the first place or DatabaseOperations.last_executed_query() subclass implementations could fall back to ​BaseDatabaseOperations.last_executed_query() rather than returning None.

It may be useful to see the failing query in the logs, but I'm open to other opinions about this. The pre-d8f093908c504ae0dbc39d3f5231f7d7920dde37 behavior is to log (0.000) NONE; args=<actual params>; ALIAS=DEFAULT.

[Mariusz Felisiak]

... or DatabaseOperations.last_executed_query() subclass implementations could fall back to ​BaseDatabaseOperations.last_executed_query() rather than returning None.

This sound like a great idea for me.