Clarify logs when process_request sends an HTTP response.

Fix #1606.

Author: aaugustin

docs/project/changelog.rst

@@ -83,6 +83,9 @@ Improvements
   when the handshake request exceeds a security limit, instead of closing
   the connection.
 
+* Clarified logs when ``process_request`` sends a plain HTTP response, without
+  attempting to open a WebSocket connection.
+
 * Added the ``reconnect_delays`` argument for customizing the delays between
   reconnection attempts in :func:`~asyncio.client.connect`, beyond existing
   ``WEBSOCKETS_BACKOFF_*`` environment variables.

src/websockets/server.py

@@ -113,6 +113,9 @@ def __init__(
                 "select_subprotocol",
                 select_subprotocol.__get__(self, self.__class__),
             )
+        # True when a WebSocket handshake was attempted via accept();
+        # False when a plain HTTP response sent by process_request().
+        self.accept_called = False
 
     def accept(self, request: Request) -> Response:
         """
@@ -136,6 +139,7 @@ def accept(self, request: Request) -> Response:
             WebSocket handshake response or HTTP response to send to the client.
 
         """
+        self.accept_called = True
         try:
             (
                 accept_header,
@@ -550,8 +554,12 @@ def send_response(self, response: Response) -> None:
             self.logger.info("connection open")
 
         else:
+            if self.accept_called:
+                log_message = "connection rejected (%d %s)"
+            else:
+                log_message = "HTTP response sent (%d %s)"
             self.logger.info(
-                "connection rejected (%d %s)",
+                log_message,
                 response.status_code,
                 response.reason_phrase,
             )

tests/test_server.py

@@ -71,12 +71,13 @@ def test_receive_request(self, _formatdate):
         self.assertFalse(server.close_expected())
         self.assertEqual(server.state, CONNECTING)
 
-    def test_accept_and_send_successful_response(self, _formatdate):
+    def test_send_response_after_accept(self, _formatdate):
         """Server accepts a handshake request and sends a successful response."""
         server = ServerProtocol()
         request = make_request()
         response = server.accept(request)
-        server.send_response(response)
+        with self.assertLogs("websockets.server", logging.INFO) as logs:
+            server.send_response(response)
 
         self.assertEqual(
             server.data_to_send(),
@@ -91,14 +92,19 @@ def test_accept_and_send_successful_response(self, _formatdate):
         )
         self.assertFalse(server.close_expected())
         self.assertEqual(server.state, OPEN)
+        self.assertEqual(
+            [record.getMessage() for record in logs.records],
+            ["connection open"],
+        )
 
-    def test_send_response_after_failed_accept(self, _formatdate):
+    def test_send_response_after_accept_failed(self, _formatdate):
         """Server accepts a handshake request but sends a failed response."""
         server = ServerProtocol()
         request = make_request()
         del request.headers["Sec-WebSocket-Key"]
         response = server.accept(request)
-        server.send_response(response)
+        with self.assertLogs("websockets.server", logging.INFO) as logs:
+            server.send_response(response)
 
         self.assertEqual(
             server.data_to_send(),
@@ -116,12 +122,17 @@ def test_send_response_after_failed_accept(self, _formatdate):
         )
         self.assertTrue(server.close_expected())
         self.assertEqual(server.state, CONNECTING)
+        self.assertEqual(
+            [record.getMessage() for record in logs.records],
+            ["connection rejected (400 Bad Request)"],
+        )
 
     def test_send_response_after_reject(self, _formatdate):
         """Server rejects a handshake request and sends a failed response."""
         server = ServerProtocol()
         response = server.reject(http.HTTPStatus.NOT_FOUND, "Sorry folks.\n")
-        server.send_response(response)
+        with self.assertLogs("websockets.server", logging.INFO) as logs:
+            server.send_response(response)
 
         self.assertEqual(
             server.data_to_send(),
@@ -138,24 +149,29 @@ def test_send_response_after_reject(self, _formatdate):
         )
         self.assertTrue(server.close_expected())
         self.assertEqual(server.state, CONNECTING)
+        self.assertEqual(
+            [record.getMessage() for record in logs.records],
+            ["HTTP response sent (404 Not Found)"],
+        )
 
     def test_send_response_without_accept_or_reject(self, _formatdate):
         """Server doesn't accept or reject and sends a failed response."""
         server = ServerProtocol()
-        server.send_response(
-            Response(
-                410,
-                "Gone",
-                Headers(
-                    {
-                        "Connection": "close",
-                        "Content-Length": "6",
-                        "Content-Type": "text/plain",
-                    }
-                ),
-                b"AWOL.\n",
-            )
+        response = Response(
+            410,
+            "Gone",
+            Headers(
+                {
+                    "Connection": "close",
+                    "Content-Length": "6",
+                    "Content-Type": "text/plain",
+                }
+            ),
+            b"AWOL.\n",
         )
+        with self.assertLogs("websockets.server", logging.INFO) as logs:
+            server.send_response(response)
+
         self.assertEqual(
             server.data_to_send(),
             [
@@ -170,6 +186,10 @@ def test_send_response_without_accept_or_reject(self, _formatdate):
         )
         self.assertTrue(server.close_expected())
         self.assertEqual(server.state, CONNECTING)
+        self.assertEqual(
+            [record.getMessage() for record in logs.records],
+            ["HTTP response sent (410 Gone)"],
+        )
 
 
 class RequestTests(unittest.TestCase):