Added elapsed time to _debug_response_sent

Author: michalpokusa

adafruit_httpserver/server.py

@@ -15,6 +15,7 @@
     pass
 
 from errno import EAGAIN, ECONNRESET, ETIMEDOUT
+from time import monotonic
 from traceback import print_exception
 
 from .authentication import Basic, Token, Bearer, require_authentication
@@ -358,6 +359,8 @@ def poll(self) -> str:
             conn, client_address = self._sock.accept()
             conn.settimeout(self._timeout)
 
+            _debug_start_time = monotonic()
+
             # Receive the whole request
             if (request := self._receive_request(conn, client_address)) is None:
                 conn.close()
@@ -378,8 +381,10 @@ def poll(self) -> str:
             # Send the response
             response._send()  # pylint: disable=protected-access
 
+            _debug_end_time = monotonic()
+
             if self.debug:
-                _debug_response_sent(response)
+                _debug_response_sent(response, _debug_end_time - _debug_start_time)
 
             return REQUEST_HANDLED_RESPONSE_SENT
 
@@ -496,7 +501,7 @@ def _debug_started_server(server: "Server"):
     print(f"Started development server on http://{host}:{port}")
 
 
-def _debug_response_sent(response: "Response"):
+def _debug_response_sent(response: "Response", time_elapsed: float):
     """Prints a message when after a response is sent."""
     # pylint: disable=protected-access
     client_ip = response._request.client_address[0]
@@ -505,8 +510,11 @@ def _debug_response_sent(response: "Response"):
     req_size = len(response._request.raw_request)
     status = response._status
     res_size = response._size
+    time_elapsed_ms = f"{round(time_elapsed*1000)}ms"
 
-    print(f'{client_ip} -- "{method} {path}" {req_size} -- "{status}" {res_size}')
+    print(
+        f'{client_ip} -- "{method} {path}" {req_size} -- "{status}" {res_size} -- {time_elapsed_ms}'
+    )
 
 
 def _debug_stopped_server(server: "Server"):  # pylint: disable=unused-argument

docs/examples.rst

@@ -357,19 +357,19 @@ occurs during handling of the request in ``.serve_forever()``.
 This is how the logs might look like when debug mode is enabled::
 
     Started development server on http://192.168.0.100:80
-    192.168.0.101 -- "GET /" 194 -- "200 OK" 154
-    192.168.0.101 -- "GET /example" 134 -- "404 Not Found" 172
-    192.168.0.102 -- "POST /api" 1241 -- "401 Unauthorized" 95
+    192.168.0.101 -- "GET /" 194 -- "200 OK" 154 -- 96ms
+    192.168.0.101 -- "GET /example" 134 -- "404 Not Found" 172 -- 123ms
+    192.168.0.102 -- "POST /api" 1241 -- "401 Unauthorized" 95 -- 64ms
     Traceback (most recent call last):
         ...
         File "code.py", line 55, in example_handler
     KeyError: non_existent_key
-    192.168.0.103 -- "GET /index.html" 242 -- "200 OK" 154
+    192.168.0.103 -- "GET /index.html" 242 -- "200 OK" 154 -- 182ms
     Stopped development server
 
 This is the default format of the logs::
 
-    {client_ip} -- "{request_method} {path}" {request_size} -- "{response_status}" {response_size}
+    {client_ip} -- "{request_method} {path}" {request_size} -- "{response_status}" {response_size} -- {elapsed_ms}
 
 If you need more information about the server or request, or you want it in a different format you can modify
 functions at the bottom of ``adafruit_httpserver/server.py`` that start with ``_debug_...``.