[Django] #35448: test --debug-sql SQL formatting is applied to more than the query

[Django]

#35448: test --debug-sql SQL formatting is applied to more than the query
---------------------------------------------+------------------------
Reporter: Tim Graham | Owner: nobody
Type: Bug | Status: new
Component: Testing framework | Version: dev
Severity: Normal | Keywords:
Triage Stage: Unreviewed | Has patch: 0
Needs documentation: 0 | Needs tests: 0
Patch needs improvement: 0 | Easy pickings: 0
UI/UX: 0 |
---------------------------------------------+------------------------
Since #34111 (3283120cca5d5eba5c3619612d0de5ad49dcf054), the output of
`manage.py test --debug-sql` is
[https://github.com/django/django/blob/a09082a9bec18f8e3ee8c10d473013ec67ffe93b/django/test/runner.py#L100
formatted with sqlparse]. Because this
[https://github.com/django/django/blob/ceaf1e2848583ba832cc74715da38c802b6b0671/django/db/backends/utils.py#L152
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)".
--
Ticket URL: <https://code.djangoproject.com/ticket/35448>
Django <https://code.djangoproject.com/>
The Web framework for perfectionists with deadlines.

[Django]

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

--------------------------------------+------------------------------------

Reporter: Tim Graham | Owner: nobody

Type: Cleanup/optimization | Status: new

Component: Testing framework | Version: dev

Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted

Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0

--------------------------------------+------------------------------------
Changes (by Natalia Bidart):

* stage: Unreviewed => Accepted
* type: Bug => Cleanup/optimization

Comment:

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.
--
Ticket URL: <https://code.djangoproject.com/ticket/35448#comment:1>

[Django]

#35448: test --debug-sql SQL formatting is applied to more than the query
--------------------------------------+------------------------------------
Reporter: Tim Graham | Owner: nobody
Type: Cleanup/optimization | Status: new
Component: Testing framework | Version: dev
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
--------------------------------------+------------------------------------

Comment (by Jae Hyuck Sa ):

I'll try to fix it!
--
Ticket URL: <https://code.djangoproject.com/ticket/35448#comment:2>

[Django]

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

-------------------------------------+-------------------------------------
Reporter: Tim Graham | Owner: Jae Hyuck
Type: | Sa
Cleanup/optimization | Status: assigned

Component: Testing framework | Version: dev
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0

-------------------------------------+-------------------------------------
Changes (by Jae Hyuck Sa ):

* owner: nobody => Jae Hyuck Sa
* status: new => assigned

--
Ticket URL: <https://code.djangoproject.com/ticket/35448#comment:3>

[Django]

#35448: test --debug-sql SQL formatting is applied to more than the query
-------------------------------------+-------------------------------------
Reporter: Tim Graham | Owner: Jae Hyuck
Type: | Sa
Cleanup/optimization | Status: assigned
Component: Testing framework | Version: dev
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted

Has patch: 1 | Needs documentation: 0

Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------
Changes (by Jae Hyuck Sa ):

* has_patch: 0 => 1

--
Ticket URL: <https://code.djangoproject.com/ticket/35448#comment:4>

[Django]

#35448: test --debug-sql SQL formatting is applied to more than the query
-------------------------------------+-------------------------------------
Reporter: Tim Graham | Owner: Jae Hyuck
Type: | Sa
Cleanup/optimization | Status: assigned
Component: Testing framework | Version: dev
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0

Needs tests: 0 | Patch needs improvement: 1

Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Changes (by Mariusz Felisiak):

* needs_better_patch: 0 => 1

--
Ticket URL: <https://code.djangoproject.com/ticket/35448#comment:5>

[Django]

#35448: test --debug-sql SQL formatting is applied to more than the query
-------------------------------------+-------------------------------------
Reporter: Tim Graham | Owner: Jae Hyuck
Type: | Sa
Cleanup/optimization | Status: assigned
Component: Testing framework | Version: dev
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0

Needs tests: 0 | Patch needs improvement: 0

Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Changes (by Jae Hyuck Sa ):

* needs_better_patch: 1 => 0

--
Ticket URL: <https://code.djangoproject.com/ticket/35448#comment:6>

[Django]

#35448: test --debug-sql SQL formatting is applied to more than the query
-------------------------------------+-------------------------------------
Reporter: Tim Graham | Owner: Jae Hyuck
Type: | Sa
Cleanup/optimization | Status: assigned
Component: Testing framework | Version: dev
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Comment (by Jae Hyuck Sa ):

I reverted the
[commit(3283120)](https://github.com/django/django/commit/3283120cca5d5eba5c3619612d0de5ad49dcf054)
to resolving the issue of the ticket
--
Ticket URL: <https://code.djangoproject.com/ticket/35448#comment:7>

[Django]

#35448: test --debug-sql SQL formatting is applied to more than the query
-------------------------------------+-------------------------------------
Reporter: Tim Graham | Owner: Jae Hyuck
Type: | Sa
Cleanup/optimization | Status: assigned
Component: Testing framework | Version: dev
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0

Needs tests: 1 | Patch needs improvement: 1

Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Changes (by Mariusz Felisiak):

* needs_better_patch: 0 => 1

* needs_tests: 0 => 1

--
Ticket URL: <https://code.djangoproject.com/ticket/35448#comment:8>

[Django]

#35448: test --debug-sql SQL formatting is applied to more than the query
-------------------------------------+-------------------------------------
Reporter: Tim Graham | Owner: Jae Hyuck
Type: | Sa
Cleanup/optimization | Status: assigned
Component: Testing framework | Version: dev
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0

Needs tests: 0 | Patch needs improvement: 0

Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Changes (by Jae Hyuck Sa ):

* needs_better_patch: 1 => 0

* needs_tests: 1 => 0

--
Ticket URL: <https://code.djangoproject.com/ticket/35448#comment:9>

[Django]

#35448: test --debug-sql SQL formatting is applied to more than the query
-------------------------------------+-------------------------------------
Reporter: Tim Graham | Owner: Jae Hyuck
Type: | Sa
Cleanup/optimization | Status: assigned
Component: Testing framework | Version: dev
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0

Needs tests: 0 | Patch needs improvement: 1

Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Changes (by Tim Graham):

* needs_better_patch: 0 => 1

Comment:

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.)
--
Ticket URL: <https://code.djangoproject.com/ticket/35448#comment:10>

[Django]

#35448: test --debug-sql SQL formatting is applied to more than the query
-------------------------------------+-------------------------------------
Reporter: Tim Graham | Owner: Jae Hyuck
Type: | Sa
Cleanup/optimization | Status: assigned
Component: Testing framework | Version: dev
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Comment (by Jae Hyuck Sa ):

Replying to [comment:10 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?
--
Ticket URL: <https://code.djangoproject.com/ticket/35448#comment:11>

[Django]

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

--------------------------------------+------------------------------------
Reporter: Tim Graham | Owner: (none)
Type: Cleanup/optimization | Status: new

Component: Testing framework | Version: dev
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 1
Easy pickings: 0 | UI/UX: 0

--------------------------------------+------------------------------------
Changes (by Jae Hyuck Sa ):

* owner: Jae Hyuck Sa => (none)
* status: assigned => new

--
Ticket URL: <https://code.djangoproject.com/ticket/35448#comment:12>

[Django]

#35448: test --debug-sql SQL formatting is applied to more than the query
--------------------------------------+------------------------------------
Reporter: Tim Graham | Owner: (none)
Type: Cleanup/optimization | Status: new
Component: Testing framework | Version: dev
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted

Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0

Easy pickings: 0 | UI/UX: 0
--------------------------------------+------------------------------------
Changes (by Jae Hyuck Sa ):

* has_patch: 1 => 0

* needs_better_patch: 1 => 0

--
Ticket URL: <https://code.djangoproject.com/ticket/35448#comment:13>

[Django]

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

-------------------------------------+-------------------------------------
Reporter: Tim Graham | Owner: Hana
Type: | Burtin
Cleanup/optimization | Status: assigned

Component: Testing framework | Version: dev
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0

-------------------------------------+-------------------------------------
Changes (by Hana Burtin):

* owner: (none) => Hana Burtin

* status: new => assigned

Comment:

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

Preparing a MR
--
Ticket URL: <https://code.djangoproject.com/ticket/35448#comment:14>

[Django]

#35448: test --debug-sql SQL formatting is applied to more than the query
-------------------------------------+-------------------------------------
Reporter: Tim Graham | Owner: Hana
Type: | Burtin
Cleanup/optimization | Status: assigned
Component: Testing framework | Version: dev
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted

Has patch: 1 | Needs documentation: 0

Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------
Changes (by Hana Burtin):

* has_patch: 0 => 1

--
Ticket URL: <https://code.djangoproject.com/ticket/35448#comment:15>

[Django]

#35448: test --debug-sql SQL formatting is applied to more than the query
-------------------------------------+-------------------------------------
Reporter: Tim Graham | Owner: Hana
Type: | Burtin
Cleanup/optimization | Status: assigned
Component: Testing framework | Version: dev
Severity: Normal | Resolution:

Keywords: | Triage Stage: Ready for
| checkin

Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------
Changes (by Hana Burtin):

* stage: Accepted => Ready for checkin

--
Ticket URL: <https://code.djangoproject.com/ticket/35448#comment:16>

[Django]

#35448: test --debug-sql SQL formatting is applied to more than the query
-------------------------------------+-------------------------------------
Reporter: Tim Graham | Owner: Hana
Type: | Burtin
Cleanup/optimization | Status: assigned
Component: Testing framework | Version: dev
Severity: Normal | Resolution:

Keywords: | Triage Stage: Accepted

Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Changes (by Tim Graham):

* stage: Ready for checkin => Accepted

Comment:

A reviewer should advance the ticket to "Ready for checkin," not the patch
author.
--
Ticket URL: <https://code.djangoproject.com/ticket/35448#comment:17>

[Django]

#35448: test --debug-sql SQL formatting is applied to more than the query
-------------------------------------+-------------------------------------
Reporter: Tim Graham | Owner: Hana
Type: | Burtin
Cleanup/optimization | Status: assigned
Component: Testing framework | Version: dev
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0

Needs tests: 1 | Patch needs improvement: 1

Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Changes (by Sarah Boyce):

* needs_better_patch: 0 => 1

* needs_tests: 0 => 1

--
Ticket URL: <https://code.djangoproject.com/ticket/35448#comment:18>

[Django]

#35448: test --debug-sql SQL formatting is applied to more than the query
-------------------------------------+-------------------------------------

Reporter: Tim Graham | Owner: Tim
Type: | Graham

Cleanup/optimization | Status: assigned
Component: Testing framework | Version: dev
Severity: Normal | Resolution:
Keywords: | Triage Stage: Accepted
Has patch: 1 | Needs documentation: 0

Needs tests: 0 | Patch needs improvement: 0

Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Changes (by Tim Graham):

* needs_better_patch: 1 => 0

* needs_tests: 1 => 0

* owner: Hana Burtin => Tim Graham

Comment:

My [https://github.com/django/django/pull/19001 PR] implements the
approach I suggested in comment:10.
--
Ticket URL: <https://code.djangoproject.com/ticket/35448#comment:19>

[Django]

#35448: test --debug-sql SQL formatting is applied to more than the query
-------------------------------------+-------------------------------------
Reporter: Tim Graham | Owner: Tim
Type: | Graham
Cleanup/optimization | Status: assigned
Component: Testing framework | Version: dev
Severity: Normal | Resolution:

Keywords: | Triage Stage: Ready for
| checkin

Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Changes (by Mariusz Felisiak):

* stage: Accepted => Ready for checkin

--
Ticket URL: <https://code.djangoproject.com/ticket/35448#comment:20>

[Django]

#35448: test --debug-sql SQL formatting is applied to more than the query
-------------------------------------+-------------------------------------
Reporter: Tim Graham | Owner: Tim
Type: | Graham

Cleanup/optimization | Status: closed

Component: Testing framework | Version: dev

Severity: Normal | Resolution: fixed

Keywords: | Triage Stage: Ready for
| checkin
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Changes (by Mariusz Felisiak <felisiak.mariusz@…>):

* resolution: => fixed
* status: assigned => closed

Comment:

In [changeset:"d8f093908c504ae0dbc39d3f5231f7d7920dde37" d8f09390]:
{{{#!CommitTicketReference repository=""
revision="d8f093908c504ae0dbc39d3f5231f7d7920dde37"
Fixed #35448 -- Fixed formatting of test --debug-sql output.

Also adds DatabaseOperations.format_debug_sql() hook for backends
(e.g. NoSQL) to customize formatting.
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/35448#comment:21>

[Django]

#35448: test --debug-sql SQL formatting is applied to more than the query
-------------------------------------+-------------------------------------
Reporter: Tim Graham | Owner: Tim
Type: | Graham
Cleanup/optimization | Status: closed
Component: Testing framework | Version: dev
Severity: Normal | Resolution: fixed
Keywords: | Triage Stage: Ready for
| checkin
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Comment (by GitHub <noreply@…>):

In [changeset:"ec8cbea91ed6362d43298caa43f3d868452f7efa" ec8cbea]:
{{{#!CommitTicketReference repository=""
revision="ec8cbea91ed6362d43298caa43f3d868452f7efa"
Refs #35448 -- Fixed BackendTestCase.test_queries_logger() on Oracle <
23c.
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/35448#comment:22>

[Django]

#35448: test --debug-sql SQL formatting is applied to more than the query
-------------------------------------+-------------------------------------
Reporter: Tim Graham | Owner: Tim
Type: | Graham
Cleanup/optimization | Status: closed
Component: Testing framework | Version: dev
Severity: Normal | Resolution: fixed
Keywords: | Triage Stage: Ready for
| checkin
Has patch: 1 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
-------------------------------------+-------------------------------------

Comment (by nessita <124304+nessita@…>):

In [changeset:"1a03a984ab3728253f964ba16cd8d806f76bddf9" 1a03a984]:
{{{#!CommitTicketReference repository=""
revision="1a03a984ab3728253f964ba16cd8d806f76bddf9"
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 <jacobty...@gmail.com>
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/35448#comment:23>