From 85cc73dca5ccebeb5bdb584257871abf1f76bc95 Mon Sep 17 00:00:00 2001 From: Sean Quah Date: Thu, 28 Apr 2022 14:03:39 +0100 Subject: [PATCH 1/3] Improve logging for cancelled requests Don't log stack traces for cancelled requests and use a custom HTTP status code of 499. Signed-off-by: Sean Quah --- synapse/http/server.py | 30 ++++++++++++++++++++++++++++++ 1 file changed, 30 insertions(+) diff --git a/synapse/http/server.py b/synapse/http/server.py index 1cf49830e89b..657bffcddd88 100644 --- a/synapse/http/server.py +++ b/synapse/http/server.py @@ -43,6 +43,7 @@ from zope.interface import implementer from twisted.internet import defer, interfaces +from twisted.internet.defer import CancelledError from twisted.python import failure from twisted.web import resource from twisted.web.server import NOT_DONE_YET, Request @@ -82,6 +83,14 @@ """ +# A fictional HTTP status code for requests where the client has disconnected and we +# successfully cancelled the request. Used only for logging purposes. Clients will never +# observe this code unless cancellations leak across requests or we raise a +# `CancelledError` ourselves. +# Analogous to nginx's 499 status code: +# https://github.com/nginx/nginx/blob/release-1.21.6/src/http/ngx_http_request.h#L128-L134 +HTTP_STATUS_REQUEST_CANCELLED = 499 + def return_json_error(f: failure.Failure, request: SynapseRequest) -> None: """Sends a JSON error response to clients.""" @@ -93,6 +102,17 @@ def return_json_error(f: failure.Failure, request: SynapseRequest) -> None: error_dict = exc.error_dict() logger.info("%s SynapseError: %s - %s", request, error_code, exc.msg) + elif f.check(CancelledError): + error_code = HTTP_STATUS_REQUEST_CANCELLED + error_dict = {"error": "Request cancelled", "errcode": Codes.UNKNOWN} + + if not request._disconnected: + logger.error( + "Got cancellation before client disconnection from %r: %r", + request.request_metrics.name, + request, + exc_info=(f.type, f.value, f.getTracebackObject()), # type: ignore[arg-type] + ) else: error_code = 500 error_dict = {"error": "Internal server error", "errcode": Codes.UNKNOWN} @@ -155,6 +175,16 @@ def return_html_error( request, exc_info=(f.type, f.value, f.getTracebackObject()), # type: ignore[arg-type] ) + elif f.check(CancelledError): + code = HTTP_STATUS_REQUEST_CANCELLED + msg = "Request cancelled" + + if not request._disconnected: + logger.error( + "Got cancellation before client disconnection when handling request %r", + request, + exc_info=(f.type, f.value, f.getTracebackObject()), # type: ignore[arg-type] + ) else: code = HTTPStatus.INTERNAL_SERVER_ERROR msg = "Internal server error" From a3e529c49ec1a2a30aafb5fc08a157d96c4b21a4 Mon Sep 17 00:00:00 2001 From: Sean Quah Date: Thu, 28 Apr 2022 18:24:58 +0100 Subject: [PATCH 2/3] Add newsfile Signed-off-by: Sean Quah --- changelog.d/12587.misc | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/12587.misc diff --git a/changelog.d/12587.misc b/changelog.d/12587.misc new file mode 100644 index 000000000000..d26e332305ce --- /dev/null +++ b/changelog.d/12587.misc @@ -0,0 +1 @@ +Add `@cancellable` decorator, for use on endpoint methods that can be cancelled when clients disconnect. From 5b4691080473bda5d7833d8eb9368342e43795f3 Mon Sep 17 00:00:00 2001 From: Sean Quah Date: Tue, 3 May 2022 15:48:58 +0100 Subject: [PATCH 3/3] Update docs on log messages to mention the new status code --- docs/usage/administration/request_log.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/usage/administration/request_log.md b/docs/usage/administration/request_log.md index 316304c7348a..adb5f4f5f353 100644 --- a/docs/usage/administration/request_log.md +++ b/docs/usage/administration/request_log.md @@ -28,7 +28,7 @@ See the following for how to decode the dense data available from the default lo | NNNN | Total time waiting for response to DB queries across all parallel DB work from this request | | OOOO | Count of DB transactions performed | | PPPP | Response body size | -| QQQQ | Response status code (prefixed with ! if the socket was closed before the response was generated) | +| QQQQ | Response status code
Suffixed with `!` if the socket was closed before the response was generated.
A `499!` status code indicates that Synapse also cancelled request processing after the socket was closed.
| | RRRR | Request | | SSSS | User-agent | | TTTT | Events fetched from DB to service this request (note that this does not include events fetched from the cache) |