"Synchronous middleware ... adapted" is not logged for synchronous middleware

[Aaron Chong]

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

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.

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

@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

# 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:

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:

  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)

[Carlton Gibson]

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

[Aaron Chong]

Hi Carlton, thanks for your comment.

PR: ​https://github.com/django/django/pull/15413

[Mariusz Felisiak <felisiak.mariusz@…>]

In 2d472ad:

Fixed #33495 -- Improved debug logging message about adapting handlers for middlewares.

It's the wrapped handler that's adapted to the wrapping middleware.