Clean up logging for full socket buffer
authoradvil <rawlins@gmail.com>
Wed, 20 Jan 2021 20:26:35 +0000 (15:26 -0500)
committeradvil <rawlins@gmail.com>
Wed, 20 Jan 2021 20:26:35 +0000 (15:26 -0500)
When holding down a key in webtiles for something that takes a long
enough time to outpace the key repeat (either because it is
cpu-intensive or just because it imposes a delay), the buffer used to
communicate with the crawl instance can fill up, which triggers an
exception (and drops the key). When this happens, it is quite spammy in
logs on live servers. Ideally this could be prevented from happening in
the first place (e.g. any time this can happen on autofight/autofire is
a case that should be better optimized), but it will inevitably happen
from time to time, and doesn't need to fill up the logs quite so much
when it does; the stack trace is not informative.

For future reference, the full stack trace for a single case of this
will look something like (with minor differences between OSs):

2021-01-20 14:05:25,059 WARN: #0     Error while handling JSON message (''{"msg":"key","keycode":9}'')!
Traceback (most recent call last):
  File "/Users/advil/repos/crawl/crawl-ref/source/webserver/ws_handler.py", line 869, in on_message
    self.process.handle_input(message)
  File "/Users/advil/repos/crawl/crawl-ref/source/webserver/process_handler.py", line 897, in handle_input
    self.conn.send_message(utf8(msg))
  File "/Users/advil/repos/crawl/crawl-ref/source/webserver/connection.py", line 109, in send_message
    self.socket.sendto(utf8(data), self.crawl_socketpath)
OSError: [Errno 55] No buffer space available

crawl-ref/source/webserver/ws_handler.py

index 0e5a3f4..dc09737 100644 (file)
@@ -877,6 +877,22 @@ class CrawlWebSocket(tornado.websocket.WebSocketHandler):
                 self.logger.warning("Didn't know how to handle msg (user %s): %s",
                                     self.username and self.username or "[Anon]",
                                     obj["msg"])
+        except OSError as e:
+            # maybe should throw a custom exception from the socket call rather
+            # than rely on these cases?
+            excerpt = message[:50] if len(message) > 50 else message
+            trunc = "..." if len(message) > 50 else ""
+            if e.errno == errno.EAGAIN or e.errno == errno.ENOBUFS:
+                # errno is different on mac vs linux, maybe also depending on
+                # python version
+                self.logger.warning(
+                    "Socket buffer full; skipping JSON message ('%r%s')!",
+                                excerpt, trunc)
+            else:
+                self.logger.warning(
+                                "Error while handling JSON message ('%r%s')!",
+                                excerpt, trunc,
+                                exc_info=True)
         except Exception:
             excerpt = message[:50] if len(message) > 50 else message
             trunc = "..." if len(message) > 50 else ""