test --debug-sql SQL formatting is applied to more than the query

[Tim Graham]

Since #34111 (3283120cca5d5eba5c3619612d0de5ad49dcf054), the output of manage.py test --debug-sql is ​formatted with sqlparse. Because this ​log message contains more than SQL (including a prefix with the query's duration as well as a suffix that includes the query parameters and database alias) there are some problems with the output.

For example:

(0.000) SELECT "basic_article"."id", "basic_article"."headline", "basic_article"."pub_date" FROM "basic_article" WHERE "basic_article"."id" = 1 LIMIT 21; args=(1,); alias=default
(0.000) SELECT "basic_article"."id", "basic_article"."headline", "basic_article"."pub_date" FROM "basic_article" WHERE "basic_article"."id" = 1 LIMIT 21; args=(1,); alias=default

becomes:

(0.000)
SELECT "basic_article"."id",
       "basic_article"."headline",
       "basic_article"."pub_date"
FROM "basic_article"
WHERE "basic_article"."id" = 1
LIMIT 21;

args=(1,);

ALIAS=DEFAULT (0.000)
SELECT "basic_article"."id",
       "basic_article"."headline",
       "basic_article"."pub_date"
FROM "basic_article"
WHERE "basic_article"."id" = 1
LIMIT 21;

args=(1,);

ALIAS=DEFAULT

"alias=default" is unexpectedly capitalized since these are SQL reserved words. There is also the addition of a newline after the duration but not at the end of the query such that the output from one query runs into the other: "ALIAS=DEFAULT (0.000)".

[Natalia Bidart]

Thank you Tim. Now that you mention it, I also noticed a weird output when posting in ticket:35381#comment:1 but I did not realize it was caused by the SQL formatting.

[Jae Hyuck Sa]

I'll try to fix it!

[Jae Hyuck Sa]

I reverted the [commit(3283120)](​https://github.com/django/django/commit/3283120cca5d5eba5c3619612d0de5ad49dcf054) to resolving the issue of the ticket

[Tim Graham]

I don't think we want any solution that involves parsing the output using regular expressions. That's too complicated. Why not format the SQL before it's added to the logging statement in db/backends/utils.py?

(Incidentally, I'm working on a MongoDB backend for Django and would like to override the formatting since it won't be SQL. If the formatting were done there, I could move the formatting to an overridable DatabaseOperations.format_sql() hook.)

[Jae Hyuck Sa]

Replying to Tim Graham:

I don't think we want any solution that involves parsing the output using regular expressions. That's too complicated. Why not format the SQL before it's added to the logging statement in db/backends/utils.py?

(Incidentally, I'm working on a MongoDB backend for Django and would like to override the formatting since it won't be SQL. If the formatting were done there, I could move the formatting to an overridable DatabaseOperations.format_sql() hook.)

I also think the regular expression is complicated. I only applied the part because I was worried that it would also apply to other logs. Am I misunderstanding or missing the overall flow?

[Hana Burtin]

We can set a workaround using the TestCase log handler and reformat the queries from here.

Preparing a MR

[Tim Graham]

A reviewer should advance the ticket to "Ready for checkin," not the patch author.

[Tim Graham]

My ​PR implements the approach I suggested in comment:10.

[Mariusz Felisiak <felisiak.mariusz@…>]

In d8f09390:

Fixed #35448 -- Fixed formatting of test --debug-sql output.

Also adds DatabaseOperations.format_debug_sql() hook for backends
(e.g. NoSQL) to customize formatting.

[GitHub <noreply@…>]

In ec8cbea:

Refs #35448 -- Fixed BackendTestCase.test_queries_logger() on Oracle < 23c.

[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@…>