diff options
Diffstat (limited to 'testing/web-platform/tests/tools/third_party/websockets/docs/topics/logging.rst')
| -rw-r--r-- | testing/web-platform/tests/tools/third_party/websockets/docs/topics/logging.rst | 245 |
1 files changed, 245 insertions, 0 deletions
diff --git a/testing/web-platform/tests/tools/third_party/websockets/docs/topics/logging.rst b/testing/web-platform/tests/tools/third_party/websockets/docs/topics/logging.rst new file mode 100644 index 0000000000..e7abd96ce5 --- /dev/null +++ b/testing/web-platform/tests/tools/third_party/websockets/docs/topics/logging.rst @@ -0,0 +1,245 @@ +Logging +======= + +.. currentmodule:: websockets + +Logs contents +------------- + +When you run a WebSocket client, your code calls coroutines provided by +websockets. + +If an error occurs, websockets tells you by raising an exception. For example, +it raises a :exc:`~exceptions.ConnectionClosed` exception if the other side +closes the connection. + +When you run a WebSocket server, websockets accepts connections, performs the +opening handshake, runs the connection handler coroutine that you provided, +and performs the closing handshake. + +Given this `inversion of control`_, if an error happens in the opening +handshake or if the connection handler crashes, there is no way to raise an +exception that you can handle. + +.. _inversion of control: https://en.wikipedia.org/wiki/Inversion_of_control + +Logs tell you about these errors. + +Besides errors, you may want to record the activity of the server. + +In a request/response protocol such as HTTP, there's an obvious way to record +activity: log one event per request/response. Unfortunately, this solution +doesn't work well for a bidirectional protocol such as WebSocket. + +Instead, when running as a server, websockets logs one event when a +`connection is established`_ and another event when a `connection is +closed`_. + +.. _connection is established: https://www.rfc-editor.org/rfc/rfc6455.html#section-4 +.. _connection is closed: https://www.rfc-editor.org/rfc/rfc6455.html#section-7.1.4 + +By default, websockets doesn't log an event for every message. That would be +excessive for many applications exchanging small messages at a fast rate. If +you need this level of detail, you could add logging in your own code. + +Finally, you can enable debug logs to get details about everything websockets +is doing. This can be useful when developing clients as well as servers. + +See :ref:`log levels <log-levels>` below for a list of events logged by +websockets logs at each log level. + +Configure logging +----------------- + +websockets relies on the :mod:`logging` module from the standard library in +order to maximize compatibility and integrate nicely with other libraries:: + + import logging + +websockets logs to the ``"websockets.client"`` and ``"websockets.server"`` +loggers. + +websockets doesn't provide a default logging configuration because +requirements vary a lot depending on the environment. + +Here's a basic configuration for a server in production:: + + logging.basicConfig( + format="%(asctime)s %(message)s", + level=logging.INFO, + ) + +Here's how to enable debug logs for development:: + + logging.basicConfig( + format="%(message)s", + level=logging.DEBUG, + ) + +Furthermore, websockets adds a ``websocket`` attribute to log records, so you +can include additional information about the current connection in logs. + +You could attempt to add information with a formatter:: + + # this doesn't work! + logging.basicConfig( + format="{asctime} {websocket.id} {websocket.remote_address[0]} {message}", + level=logging.INFO, + style="{", + ) + +However, this technique runs into two problems: + +* The formatter applies to all records. It will crash if it receives a record + without a ``websocket`` attribute. For example, this happens when logging + that the server starts because there is no current connection. + +* Even with :meth:`str.format` style, you're restricted to attribute and index + lookups, which isn't enough to implement some fairly simple requirements. + +There's a better way. :func:`~client.connect` and :func:`~server.serve` accept +a ``logger`` argument to override the default :class:`~logging.Logger`. You +can set ``logger`` to a :class:`~logging.LoggerAdapter` that enriches logs. + +For example, if the server is behind a reverse +proxy, :attr:`~legacy.protocol.WebSocketCommonProtocol.remote_address` gives +the IP address of the proxy, which isn't useful. IP addresses of clients are +provided in an HTTP header set by the proxy. + +Here's how to include them in logs, assuming they're in the +``X-Forwarded-For`` header:: + + logging.basicConfig( + format="%(asctime)s %(message)s", + level=logging.INFO, + ) + + class LoggerAdapter(logging.LoggerAdapter): + """Add connection ID and client IP address to websockets logs.""" + def process(self, msg, kwargs): + try: + websocket = kwargs["extra"]["websocket"] + except KeyError: + return msg, kwargs + xff = websocket.request_headers.get("X-Forwarded-For") + return f"{websocket.id} {xff} {msg}", kwargs + + async with websockets.serve( + ..., + # Python < 3.10 requires passing None as the second argument. + logger=LoggerAdapter(logging.getLogger("websockets.server"), None), + ): + ... + +Logging to JSON +--------------- + +Even though :mod:`logging` predates structured logging, it's still possible to +output logs as JSON with a bit of effort. + +First, we need a :class:`~logging.Formatter` that renders JSON: + +.. literalinclude:: ../../example/logging/json_log_formatter.py + +Then, we configure logging to apply this formatter:: + + handler = logging.StreamHandler() + handler.setFormatter(formatter) + + logger = logging.getLogger() + logger.addHandler(handler) + logger.setLevel(logging.INFO) + +Finally, we populate the ``event_data`` custom attribute in log records with +a :class:`~logging.LoggerAdapter`:: + + class LoggerAdapter(logging.LoggerAdapter): + """Add connection ID and client IP address to websockets logs.""" + def process(self, msg, kwargs): + try: + websocket = kwargs["extra"]["websocket"] + except KeyError: + return msg, kwargs + kwargs["extra"]["event_data"] = { + "connection_id": str(websocket.id), + "remote_addr": websocket.request_headers.get("X-Forwarded-For"), + } + return msg, kwargs + + async with websockets.serve( + ..., + # Python < 3.10 requires passing None as the second argument. + logger=LoggerAdapter(logging.getLogger("websockets.server"), None), + ): + ... + +Disable logging +--------------- + +If your application doesn't configure :mod:`logging`, Python outputs messages +of severity ``WARNING`` and higher to :data:`~sys.stderr`. As a consequence, +you will see a message and a stack trace if a connection handler coroutine +crashes or if you hit a bug in websockets. + +If you want to disable this behavior for websockets, you can add +a :class:`~logging.NullHandler`:: + + logging.getLogger("websockets").addHandler(logging.NullHandler()) + +Additionally, if your application configures :mod:`logging`, you must disable +propagation to the root logger, or else its handlers could output logs:: + + logging.getLogger("websockets").propagate = False + +Alternatively, you could set the log level to ``CRITICAL`` for the +``"websockets"`` logger, as the highest level currently used is ``ERROR``:: + + logging.getLogger("websockets").setLevel(logging.CRITICAL) + +Or you could configure a filter to drop all messages:: + + logging.getLogger("websockets").addFilter(lambda record: None) + +.. _log-levels: + +Log levels +---------- + +Here's what websockets logs at each level. + +``ERROR`` +......... + +* Exceptions raised by connection handler coroutines in servers +* Exceptions resulting from bugs in websockets + +``WARNING`` +........... + +* Failures in :func:`~websockets.broadcast` + +``INFO`` +........ + +* Server starting and stopping +* Server establishing and closing connections +* Client reconnecting automatically + +``DEBUG`` +......... + +* Changes to the state of connections +* Handshake requests and responses +* All frames sent and received +* Steps to close a connection +* Keepalive pings and pongs +* Errors handled transparently + +Debug messages have cute prefixes that make logs easier to scan: + +* ``>`` - send something +* ``<`` - receive something +* ``=`` - set connection state +* ``x`` - shut down connection +* ``%`` - manage pings and pongs +* ``!`` - handle errors and timeouts |