logging.rst (8032B)
1 Logging 2 ======= 3 4 .. currentmodule:: websockets 5 6 Logs contents 7 ------------- 8 9 When you run a WebSocket client, your code calls coroutines provided by 10 websockets. 11 12 If an error occurs, websockets tells you by raising an exception. For example, 13 it raises a :exc:`~exceptions.ConnectionClosed` exception if the other side 14 closes the connection. 15 16 When you run a WebSocket server, websockets accepts connections, performs the 17 opening handshake, runs the connection handler coroutine that you provided, 18 and performs the closing handshake. 19 20 Given this `inversion of control`_, if an error happens in the opening 21 handshake or if the connection handler crashes, there is no way to raise an 22 exception that you can handle. 23 24 .. _inversion of control: https://en.wikipedia.org/wiki/Inversion_of_control 25 26 Logs tell you about these errors. 27 28 Besides errors, you may want to record the activity of the server. 29 30 In a request/response protocol such as HTTP, there's an obvious way to record 31 activity: log one event per request/response. Unfortunately, this solution 32 doesn't work well for a bidirectional protocol such as WebSocket. 33 34 Instead, when running as a server, websockets logs one event when a 35 `connection is established`_ and another event when a `connection is 36 closed`_. 37 38 .. _connection is established: https://www.rfc-editor.org/rfc/rfc6455.html#section-4 39 .. _connection is closed: https://www.rfc-editor.org/rfc/rfc6455.html#section-7.1.4 40 41 By default, websockets doesn't log an event for every message. That would be 42 excessive for many applications exchanging small messages at a fast rate. If 43 you need this level of detail, you could add logging in your own code. 44 45 Finally, you can enable debug logs to get details about everything websockets 46 is doing. This can be useful when developing clients as well as servers. 47 48 See :ref:`log levels <log-levels>` below for a list of events logged by 49 websockets logs at each log level. 50 51 Configure logging 52 ----------------- 53 54 websockets relies on the :mod:`logging` module from the standard library in 55 order to maximize compatibility and integrate nicely with other libraries:: 56 57 import logging 58 59 websockets logs to the ``"websockets.client"`` and ``"websockets.server"`` 60 loggers. 61 62 websockets doesn't provide a default logging configuration because 63 requirements vary a lot depending on the environment. 64 65 Here's a basic configuration for a server in production:: 66 67 logging.basicConfig( 68 format="%(asctime)s %(message)s", 69 level=logging.INFO, 70 ) 71 72 Here's how to enable debug logs for development:: 73 74 logging.basicConfig( 75 format="%(message)s", 76 level=logging.DEBUG, 77 ) 78 79 Furthermore, websockets adds a ``websocket`` attribute to log records, so you 80 can include additional information about the current connection in logs. 81 82 You could attempt to add information with a formatter:: 83 84 # this doesn't work! 85 logging.basicConfig( 86 format="{asctime} {websocket.id} {websocket.remote_address[0]} {message}", 87 level=logging.INFO, 88 style="{", 89 ) 90 91 However, this technique runs into two problems: 92 93 * The formatter applies to all records. It will crash if it receives a record 94 without a ``websocket`` attribute. For example, this happens when logging 95 that the server starts because there is no current connection. 96 97 * Even with :meth:`str.format` style, you're restricted to attribute and index 98 lookups, which isn't enough to implement some fairly simple requirements. 99 100 There's a better way. :func:`~client.connect` and :func:`~server.serve` accept 101 a ``logger`` argument to override the default :class:`~logging.Logger`. You 102 can set ``logger`` to a :class:`~logging.LoggerAdapter` that enriches logs. 103 104 For example, if the server is behind a reverse 105 proxy, :attr:`~legacy.protocol.WebSocketCommonProtocol.remote_address` gives 106 the IP address of the proxy, which isn't useful. IP addresses of clients are 107 provided in an HTTP header set by the proxy. 108 109 Here's how to include them in logs, assuming they're in the 110 ``X-Forwarded-For`` header:: 111 112 logging.basicConfig( 113 format="%(asctime)s %(message)s", 114 level=logging.INFO, 115 ) 116 117 class LoggerAdapter(logging.LoggerAdapter): 118 """Add connection ID and client IP address to websockets logs.""" 119 def process(self, msg, kwargs): 120 try: 121 websocket = kwargs["extra"]["websocket"] 122 except KeyError: 123 return msg, kwargs 124 xff = websocket.request_headers.get("X-Forwarded-For") 125 return f"{websocket.id} {xff} {msg}", kwargs 126 127 async with websockets.serve( 128 ..., 129 # Python < 3.10 requires passing None as the second argument. 130 logger=LoggerAdapter(logging.getLogger("websockets.server"), None), 131 ): 132 ... 133 134 Logging to JSON 135 --------------- 136 137 Even though :mod:`logging` predates structured logging, it's still possible to 138 output logs as JSON with a bit of effort. 139 140 First, we need a :class:`~logging.Formatter` that renders JSON: 141 142 .. literalinclude:: ../../example/logging/json_log_formatter.py 143 144 Then, we configure logging to apply this formatter:: 145 146 handler = logging.StreamHandler() 147 handler.setFormatter(formatter) 148 149 logger = logging.getLogger() 150 logger.addHandler(handler) 151 logger.setLevel(logging.INFO) 152 153 Finally, we populate the ``event_data`` custom attribute in log records with 154 a :class:`~logging.LoggerAdapter`:: 155 156 class LoggerAdapter(logging.LoggerAdapter): 157 """Add connection ID and client IP address to websockets logs.""" 158 def process(self, msg, kwargs): 159 try: 160 websocket = kwargs["extra"]["websocket"] 161 except KeyError: 162 return msg, kwargs 163 kwargs["extra"]["event_data"] = { 164 "connection_id": str(websocket.id), 165 "remote_addr": websocket.request_headers.get("X-Forwarded-For"), 166 } 167 return msg, kwargs 168 169 async with websockets.serve( 170 ..., 171 # Python < 3.10 requires passing None as the second argument. 172 logger=LoggerAdapter(logging.getLogger("websockets.server"), None), 173 ): 174 ... 175 176 Disable logging 177 --------------- 178 179 If your application doesn't configure :mod:`logging`, Python outputs messages 180 of severity ``WARNING`` and higher to :data:`~sys.stderr`. As a consequence, 181 you will see a message and a stack trace if a connection handler coroutine 182 crashes or if you hit a bug in websockets. 183 184 If you want to disable this behavior for websockets, you can add 185 a :class:`~logging.NullHandler`:: 186 187 logging.getLogger("websockets").addHandler(logging.NullHandler()) 188 189 Additionally, if your application configures :mod:`logging`, you must disable 190 propagation to the root logger, or else its handlers could output logs:: 191 192 logging.getLogger("websockets").propagate = False 193 194 Alternatively, you could set the log level to ``CRITICAL`` for the 195 ``"websockets"`` logger, as the highest level currently used is ``ERROR``:: 196 197 logging.getLogger("websockets").setLevel(logging.CRITICAL) 198 199 Or you could configure a filter to drop all messages:: 200 201 logging.getLogger("websockets").addFilter(lambda record: None) 202 203 .. _log-levels: 204 205 Log levels 206 ---------- 207 208 Here's what websockets logs at each level. 209 210 ``ERROR`` 211 ......... 212 213 * Exceptions raised by connection handler coroutines in servers 214 * Exceptions resulting from bugs in websockets 215 216 ``WARNING`` 217 ........... 218 219 * Failures in :func:`~websockets.broadcast` 220 221 ``INFO`` 222 ........ 223 224 * Server starting and stopping 225 * Server establishing and closing connections 226 * Client reconnecting automatically 227 228 ``DEBUG`` 229 ......... 230 231 * Changes to the state of connections 232 * Handshake requests and responses 233 * All frames sent and received 234 * Steps to close a connection 235 * Keepalive pings and pongs 236 * Errors handled transparently 237 238 Debug messages have cute prefixes that make logs easier to scan: 239 240 * ``>`` - send something 241 * ``<`` - receive something 242 * ``=`` - set connection state 243 * ``x`` - shut down connection 244 * ``%`` - manage pings and pongs 245 * ``!`` - handle errors and timeouts