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!

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