Subclasses of BaseDatabaseOperations should fall back to super().last_executed_query() instead of returning None

[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.

[Natalia Bidart]

I believe my work from ticket #36380 (​https://github.com/django/django/pull/19512) solves the reported crash since format_debug_sql is no longer called on the result of last_executed_query. The new SQLFormatter would only call format_debug_sql for truthy values of SQL, so, strictly speaking, the ticket would be solved. Though, I understand that there is a desire to make further improvements to last_executed_query, in that case, we could downgrade this ticket to not-release-blocker and repurpose it. What do you all think?

[Jacob Walls]

That sounds like the right course of action to me.

[nessita <124304+nessita@…>]

In 1a03a984:

Fixed #36380 -- Deferred SQL formatting when running tests with --debug-sql.

Thanks to Jacob Walls for the report and previous iterations of this
fix, to Simon Charette for the logging formatter idea, and to Tim Graham
for testing and ensuring that 3rd party backends remain compatible.

This partially reverts d8f093908c504ae0dbc39d3f5231f7d7920dde37.

Refs #36112, #35448.

Co-authored-by: Jacob Walls <jacobtylerwalls@…>