[Django] #33495: "Synchronous middleware ... adapted" is not logged for synchronous middleware
Django
middleware
----------------------------------------+-----------------------------
Reporter: Aaron Chong | Owner: Aaron Chong
Type: Bug | Status: assigned
Component: Core (Other) | Version: 4.0
Severity: Normal | Keywords: async
Triage Stage: Unreviewed | Has patch: 0
Needs documentation: 0 | Needs tests: 0
Patch needs improvement: 0 | Easy pickings: 0
UI/UX: 0 |
----------------------------------------+-----------------------------
This is a bug in log messages that contradicts the guide in a warning in
the docs; the feature works.
The guide at https://docs.djangoproject.com/en/4.0/topics/async/#async-
views, **emphasis** mine:
Warning
[[BR]]
You will only get the benefits of a fully-asynchronous request stack if
you have no synchronous middleware loaded into your site. **If there is a
piece of synchronous middleware, then Django must use a thread per request
to safely emulate a synchronous environment for it.**
[[BR]]
Middleware can be built to support both sync and async contexts. Some of
Django’s middleware is built like this, but not all. **To see what
middleware Django has to adapt, you can turn on debug logging for the
django.request logger and look for log messages about “Synchronous
middleware … adapted”.**
The test for "Synchronous middleware ... adapted" is instead testing an
async middleware over a sync method:
https://github.com/django/django/blob/7ca7f4495ba746279b734695a8dd137bf7ee0bab/tests/middleware_exceptions/tests.py#L222-L234
{{{#!python
@override_settings(MIDDLEWARE=[
'middleware_exceptions.middleware.async_payment_middleware',
])
def test_async_middleware(self):
with self.assertLogs('django.request', 'DEBUG') as cm:
response = self.client.get('/middleware_exceptions/view/')
self.assertEqual(response.status_code, 402)
self.assertEqual(
cm.records[0].getMessage(),
"Synchronous middleware "
"middleware_exceptions.middleware.async_payment_middleware "
"adapted.",
)
}}}
About the existing implementation:
1. `BaseHandler.load_middleware` passes the middleware name as `name` to
`BaseHandler.adapt_method_mode`:
https://github.com/django/django/blob/98ad327864aed8df245fd19ea9d2743279e11643/django/core/handlers/base.py#L53-L57
{{{#!python
# Adapt handler, if needed.
adapted_handler = self.adapt_method_mode(
middleware_is_async, handler, handler_is_async,
debug=settings.DEBUG, name='middleware %s' % middleware_path,
)
}}}
2. `BaseHandler.adapt_method_mode` adapts the `method` and treats `name`
as the method name rather than the middleware name; when the middleware
name is used, it implies a method has been adapted for the middleware, not
that the middleware was adapted:
{{{#!python
if debug and not name:
name = name or 'method %s()' % method.__qualname__
if is_async:
if not method_is_async:
if debug:
logger.debug('Synchronous %s adapted.', name)
return sync_to_async(method, thread_sensitive=True)
elif method_is_async:
if debug:
logger.debug('Asynchronous %s adapted.', name)
return async_to_sync(method)
}}}
Proposed fix:
Handle middleware `name` and method name separately within
`BaseHandler.adapt_method_mode`:
{{{#!diff
def adapt_method_mode(
self, is_async, method, method_is_async=None, debug=False,
name=None,
):
"""
Adapt a method to be in the correct "mode":
- If is_async is False:
- Synchronous methods are left alone
- Asynchronous methods are wrapped with async_to_sync
- If is_async is True:
- Synchronous methods are wrapped with sync_to_async()
- Asynchronous methods are left alone
"""
+ method_name = None
if method_is_async is None:
method_is_async = asyncio.iscoroutinefunction(method)
if debug and not name:
- name = name or 'method %s()' % method.__qualname__
+ method_name = 'method %s()' % method.__qualname__
if is_async:
if not method_is_async:
if debug:
- logger.debug('Synchronous %s adapted.', name)
+ if name:
+ logger.debug('Asynchronous %s adapted.', name)
+ else:
+ logger.debug('Synchronous %s adapted.', method_name)
return sync_to_async(method, thread_sensitive=True)
elif method_is_async:
if debug:
- logger.debug('Asynchronous %s adapted.', name)
+ if name:
+ logger.debug('Synchronous %s adapted.', name)
+ else:
+ logger.debug('Asynchronous %s adapted.', method_name)
return async_to_sync(method)
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/33495>
Django <https://code.djangoproject.com/>
The Web framework for perfectionists with deadlines.
Django
middleware
Reporter: Aaron Chong | Owner: Aaron
Cleanup/optimization | Status: assigned
Component: Core (Other) | Version: 4.0
Keywords: async | Triage Stage: Accepted
Has patch: 0 | Needs documentation: 0
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Carlton Gibson):
* type: Bug => Cleanup/optimization
* stage: Unreviewed => Accepted
Comment:
OK, pending Andrew's comment, I'm going to accept this as a potential
cleanup.
It's the wrapped handler that's adapted to the wrapping middleware. So, I
agree that the existing message perhaps implies the wrong thing:
{{{
Synchronous middleware
middleware_exceptions.middleware.async_payment_middleware adapted.
}}}
(in `./runtests.py
middleware_exceptions.tests.MiddlewareSyncAsyncTests.test_async_middleware`)
Here it's the (sync) `BaseHandler._get_response()` that's actually
adapted, via `return sync_to_async(method, thread_sensitive=True)`
(ln119).
Tweaking the message to something like, `Synchronous handler adapted for
middleware_exceptions.middleware.async_payment_middleware middleware.`
would be perhaps clearer 🤔
(I'd like to keep the messaging consistent on each branch — i.e. not
mixing `Synchronous` and `Asynchronous` in the messages — as that lets you
search for the log message without doubt as to which branch you're on,
even if we can improve the exact wording.)
--
Ticket URL: <https://code.djangoproject.com/ticket/33495#comment:1>
Django
middleware
Reporter: Aaron Chong | Owner: Aaron
Cleanup/optimization | Status: assigned
Component: Core (Other) | Version: 4.0
Keywords: async | Triage Stage: Accepted
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Aaron Chong):
* has_patch: 0 => 1
Comment:
Hi Carlton, thanks for your comment.
PR: https://github.com/django/django/pull/15413/files
--
Ticket URL: <https://code.djangoproject.com/ticket/33495#comment:2>
Django
middleware
Reporter: Aaron Chong | Owner: Aaron
Cleanup/optimization | Status: assigned
Component: Core (Other) | Version: 4.0
Keywords: async | 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/33495#comment:3>
Django
middleware
Reporter: Aaron Chong | Owner: Aaron
Cleanup/optimization | Status: closed
Component: Core (Other) | Version: 4.0
Keywords: async | Triage Stage: Ready for
| checkin
Needs tests: 0 | Patch needs improvement: 0
Easy pickings: 0 | UI/UX: 0
Changes (by Mariusz Felisiak <felisiak.mariusz@…>):
* status: assigned => closed
* resolution: => fixed
Comment:
In [changeset:"2d472ad05c7fb2a5fe405be46af2062cdb5eaeee" 2d472ad]:
{{{
#!CommitTicketReference repository=""
revision="2d472ad05c7fb2a5fe405be46af2062cdb5eaeee"
Fixed #33495 -- Improved debug logging message about adapting handlers for
middlewares.
It's the wrapped handler that's adapted to the wrapping middleware.
}}}
--
Ticket URL: <https://code.djangoproject.com/ticket/33495#comment:4>