Enable gunicorn logging for h11 impl

uvicorn/protocols/http/h11_impl.py

@@ -1,11 +1,14 @@
 import asyncio
 import http
 import logging
+import time
+import traceback
 from typing import Callable
 from urllib.parse import unquote
 
 import h11
 
+from uvicorn.logging import GunicornSafeAtoms
 from uvicorn.protocols.http.flow_control import (
     CLOSE_HEADER,
     HIGH_WATER_LIMIT,
@@ -169,6 +172,11 @@ def handle_events(self):
                     "raw_path": raw_path,
                     "query_string": query_string,
                     "headers": self.headers,
+                    "extensions": {
+                        "uvicorn_request_duration": {
+                            "request_start_time": time.monotonic(),
+                        }
+                    },
                 }
 
                 for name, value in self.headers:
@@ -197,6 +205,7 @@ def handle_events(self):
                     logger=self.logger,
                     access_logger=self.access_logger,
                     access_log=self.access_log,
+                    gunicorn_log=self.config.gunicorn_log,
                     default_headers=self.default_headers,
                     message_event=asyncio.Event(),
                     on_response=self.on_response_complete,
@@ -333,6 +342,7 @@ def __init__(
         logger,
         access_logger,
         access_log,
+        gunicorn_log,
         default_headers,
         message_event,
         on_response,
@@ -344,6 +354,7 @@ def __init__(
         self.logger = logger
         self.access_logger = access_logger
         self.access_log = access_log
+        self.gunicorn_log = gunicorn_log
         self.default_headers = default_headers
         self.message_event = message_event
         self.on_response = on_response
@@ -361,6 +372,12 @@ def __init__(
         self.response_started = False
         self.response_complete = False
 
+        # For logging
+        if self.gunicorn_log:
+            self.gunicorn_atoms = GunicornSafeAtoms(self.scope)
+        else:
+            self.gunicorn_atoms = None
+
     # ASGI exception wrapper
     async def run_asgi(self, app):
         try:
@@ -413,6 +430,9 @@ async def send(self, message):
         if self.disconnected:
             return
 
+        if self.gunicorn_atoms is not None:
+            self.gunicorn_atoms.on_asgi_message(message)
+
         if not self.response_started:
             # Sending response status line and headers
             if message_type != "http.response.start":
@@ -428,7 +448,7 @@ async def send(self, message):
             if CLOSE_HEADER in self.scope["headers"] and CLOSE_HEADER not in headers:
                 headers = headers + [CLOSE_HEADER]
 
-            if self.access_log:
+            if self.access_log and self.gunicorn_log is None:
                 self.access_logger.info(
                     '%s - "%s %s HTTP/%s" %d',
                     get_client_addr(self.scope),
@@ -469,6 +489,18 @@ async def send(self, message):
                 self.message_event.set()
                 event = h11.EndOfMessage()
                 output = self.conn.send(event)
+
+                duration_extension = self.scope['extensions']['uvicorn_request_duration']
+                duration_extension["response_end_time"] = time.monotonic()
+                if self.gunicorn_log is not None:
+                    try:
+                        self.gunicorn_log.access_log.info(
+                            self.gunicorn_log.cfg.access_log_format,
+                            self.gunicorn_atoms,
+                        )
+                    except:  # noqa
+                        self.gunicorn_log.error(traceback.format_exc())
+
                 self.transport.write(output)
 
         else:

uvicorn/protocols/http/httptools_impl.py

@@ -429,15 +429,15 @@ async def send_500_response(self):
     async def send(self, message):
         message_type = message["type"]
 
-        if self.gunicorn_atoms is not None:
-            self.gunicorn_atoms.on_asgi_message(message)
-
         if self.flow.write_paused and not self.disconnected:
             await self.flow.drain()
 
         if self.disconnected:
             return
 
+        if self.gunicorn_atoms is not None:
+            self.gunicorn_atoms.on_asgi_message(message)
+
         if not self.response_started:
             # Sending response status line and headers
             if message_type != "http.response.start":
@@ -453,7 +453,7 @@ async def send(self, message):
             if CLOSE_HEADER in self.scope["headers"] and CLOSE_HEADER not in headers:
                 headers = headers + [CLOSE_HEADER]
 
-            if self.access_log and not self.gunicorn_log:
+            if self.access_log and self.gunicorn_log is None:
                 self.access_logger.info(
                     '%s - "%s %s HTTP/%s" %d',
                     get_client_addr(self.scope),
@@ -531,14 +531,13 @@ async def send(self, message):
                 duration_extension = self.scope['extensions']['uvicorn_request_duration']
                 duration_extension['response_end_time'] = time.monotonic()
 
-                if self.gunicorn_log:
+                if self.gunicorn_log is not None:
                     try:
                         self.gunicorn_log.access_log.info(
                             self.gunicorn_log.cfg.access_log_format,
                             self.gunicorn_atoms,
                         )
-                    except:
-                        import traceback
+                    except:  # noqa
                         self.gunicorn_log.error(traceback.format_exc())
 
                 self.message_event.set()