Clean up prefixes of debug log messages.

All debug messages and only debug messages should have them.

Author: aaugustin

docs/topics/logging.rst

@@ -218,7 +218,10 @@ Here's what websockets logs at each level.
 ``ERROR``
 .........
 
-* Exceptions raised by connection handler coroutines in servers
+* Exceptions raised by your code in servers
+    * connection handler coroutines
+    * ``select_subprotocol`` callbacks
+    * ``process_request`` and ``process_response`` callbacks
 * Exceptions resulting from bugs in websockets
 
 ``WARNING``
@@ -250,4 +253,5 @@ Debug messages have cute prefixes that make logs easier to scan:
 * ``=`` - set connection state
 * ``x`` - shut down connection
 * ``%`` - manage pings and pongs
-* ``!`` - handle errors and timeouts
+* ``-`` - timeout
+* ``!`` - error, with a traceback

src/websockets/asyncio/client.py

@@ -521,7 +521,7 @@ async def __aiter__(self) -> AsyncIterator[ClientConnection]:
                     delays = backoff()
                 delay = next(delays)
                 self.logger.info(
-                    "! connect failed; reconnecting in %.1f seconds",
+                    "connect failed; reconnecting in %.1f seconds",
                     delay,
                     exc_info=True,
                 )

src/websockets/asyncio/connection.py

@@ -785,7 +785,7 @@ async def keepalive(self) -> None:
                         self.logger.debug("% received keepalive pong")
                     except asyncio.TimeoutError:
                         if self.debug:
-                            self.logger.debug("! timed out waiting for keepalive pong")
+                            self.logger.debug("- timed out waiting for keepalive pong")
                         async with self.send_context():
                             self.protocol.fail(
                                 CloseCode.INTERNAL_ERROR,
@@ -866,7 +866,7 @@ async def send_context(
                     await self.drain()
                 except Exception as exc:
                     if self.debug:
-                        self.logger.debug("error while sending data", exc_info=True)
+                        self.logger.debug("! error while sending data", exc_info=True)
                     # While the only expected exception here is OSError,
                     # other exceptions would be treated identically.
                     wait_for_close = False
@@ -1042,7 +1042,7 @@ def data_received(self, data: bytes) -> None:
             self.send_data()
         except Exception as exc:
             if self.debug:
-                self.logger.debug("error while sending data", exc_info=True)
+                self.logger.debug("! error while sending data", exc_info=True)
             self.set_recv_exc(exc)
 
         if self.protocol.close_expected():

src/websockets/legacy/client.py

@@ -603,14 +603,14 @@ async def __aiter__(self) -> AsyncIterator[WebSocketClientProtocol]:
                 if backoff_delay == self.BACKOFF_MIN:
                     initial_delay = random.random() * self.BACKOFF_INITIAL
                     self.logger.info(
-                        "! connect failed; reconnecting in %.1f seconds",
+                        "connect failed; reconnecting in %.1f seconds",
                         initial_delay,
                         exc_info=True,
                     )
                     await asyncio.sleep(initial_delay)
                 else:
                     self.logger.info(
-                        "! connect failed again; retrying in %d seconds",
+                        "connect failed again; retrying in %d seconds",
                         int(backoff_delay),
                         exc_info=True,
                     )

src/websockets/legacy/protocol.py

@@ -1246,7 +1246,7 @@ async def keepalive_ping(self) -> None:
                         self.logger.debug("% received keepalive pong")
                     except asyncio.TimeoutError:
                         if self.debug:
-                            self.logger.debug("! timed out waiting for keepalive pong")
+                            self.logger.debug("- timed out waiting for keepalive pong")
                         self.fail_connection(
                             CloseCode.INTERNAL_ERROR,
                             "keepalive ping timeout",
@@ -1288,7 +1288,7 @@ async def close_connection(self) -> None:
                 if await self.wait_for_connection_lost():
                     return
                 if self.debug:
-                    self.logger.debug("! timed out waiting for TCP close")
+                    self.logger.debug("- timed out waiting for TCP close")
 
             # Half-close the TCP connection if possible (when there's no TLS).
             if self.transport.can_write_eof():
@@ -1306,7 +1306,7 @@ async def close_connection(self) -> None:
                 if await self.wait_for_connection_lost():
                     return
                 if self.debug:
-                    self.logger.debug("! timed out waiting for TCP close")
+                    self.logger.debug("- timed out waiting for TCP close")
 
         finally:
             # The try/finally ensures that the transport never remains open,
@@ -1332,7 +1332,7 @@ async def close_transport(self) -> None:
         if await self.wait_for_connection_lost():
             return
         if self.debug:
-            self.logger.debug("! timed out waiting for TCP close")
+            self.logger.debug("- timed out waiting for TCP close")
 
         # Abort the TCP connection. Buffers are discarded.
         if self.debug:

src/websockets/sync/connection.py

@@ -640,7 +640,10 @@ def recv_events(self) -> None:
                     data = self.socket.recv(self.recv_bufsize)
                 except Exception as exc:
                     if self.debug:
-                        self.logger.debug("error while receiving data", exc_info=True)
+                        self.logger.debug(
+                            "! error while receiving data",
+                            exc_info=True,
+                        )
                     # When the closing handshake is initiated by our side,
                     # recv() may block until send_context() closes the socket.
                     # In that case, send_context() already set recv_exc.
@@ -665,7 +668,10 @@ def recv_events(self) -> None:
                         self.send_data()
                     except Exception as exc:
                         if self.debug:
-                            self.logger.debug("error while sending data", exc_info=True)
+                            self.logger.debug(
+                                "! error while sending data",
+                                exc_info=True,
+                            )
                         # Similarly to the above, avoid overriding an exception
                         # set by send_context(), in case of a race condition
                         # i.e. send_context() closes the socket after recv()
@@ -783,7 +789,10 @@ def send_context(
                         self.send_data()
                     except Exception as exc:
                         if self.debug:
-                            self.logger.debug("error while sending data", exc_info=True)
+                            self.logger.debug(
+                                "! error while sending data",
+                                exc_info=True,
+                            )
                         # While the only expected exception here is OSError,
                         # other exceptions would be treated identically.
                         wait_for_close = False

tests/legacy/test_client_server.py

@@ -1615,12 +1615,12 @@ async def run_client():
             [
                 "connection rejected (503 Service Unavailable)",
                 "connection closed",
-                "! connect failed; reconnecting in X seconds",
+                "connect failed; reconnecting in X seconds",
             ]
             + [
                 "connection rejected (503 Service Unavailable)",
                 "connection closed",
-                "! connect failed again; retrying in X seconds",
+                "connect failed again; retrying in X seconds",
             ]
             * ((len(logs.records) - 8) // 3)
             + [