tileradotorg/synapse
1
0
Fork 0
forked from MirrorHub/synapse
Code Pull requests Activity

Improve logging for cancelled requests (#12587)

Browse source 
Don't log stack traces for cancelled requests and use a custom HTTP
status code of 499.

Signed-off-by: Sean Quah <seanq@element.io>
This commit is contained in:
Sean Quah 2022-05-04 13:38:55 +01:00 committed by GitHub
parent 75dff3dc98
commit b2df0716bc
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
3 changed files with 32 additions and 1 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

1
changelog.d/12587.misc Normal file
View file

@ -0,0 +1 @@
Add `@cancellable` decorator, for use on endpoint methods that can be cancelled when clients disconnect.

2
docs/usage/administration/request_log.md
View file

@ -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 | | NNNN | Total time waiting for response to DB queries across all parallel DB work from this request |
| OOOO | Count of DB transactions performed | | OOOO | Count of DB transactions performed |
| PPPP | Response body size | | PPPP | Response body size |
| QQQQ | Response status code (prefixed with ! if the socket was closed before the response was generated) | | QQQQ | Response status code<br/>Suffixed with `!` if the socket was closed before the response was generated.<br/>A `499!` status code indicates that Synapse also cancelled request processing after the socket was closed.<br/> |
| RRRR | Request | | RRRR | Request |
| SSSS | User-agent | | SSSS | User-agent |
| TTTT | Events fetched from DB to service this request (note that this does not include events fetched from the cache) | | TTTT | Events fetched from DB to service this request (note that this does not include events fetched from the cache) |

30
synapse/http/server.py
View file

@ -43,6 +43,7 @@ from typing_extensions import Protocol
from zope.interface import implementer from zope.interface import implementer
from twisted.internet import defer, interfaces from twisted.internet import defer, interfaces
from twisted.internet.defer import CancelledError
from twisted.python import failure from twisted.python import failure
from twisted.web import resource from twisted.web import resource
from twisted.web.server import NOT_DONE_YET, Request from twisted.web.server import NOT_DONE_YET, Request
@ -82,6 +83,14 @@ HTML_ERROR_TEMPLATE = """<!DOCTYPE html>
</html> </html>
""" """
# 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: def return_json_error(f: failure.Failure, request: SynapseRequest) -> None:
"""Sends a JSON error response to clients.""" """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() error_dict = exc.error_dict()
logger.info("%s SynapseError: %s - %s", request, error_code, exc.msg) 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: else:
error_code = 500 error_code = 500
error_dict = {"error": "Internal server error", "errcode": Codes.UNKNOWN} error_dict = {"error": "Internal server error", "errcode": Codes.UNKNOWN}
@ -155,6 +175,16 @@ def return_html_error(
request, request,
exc_info=(f.type, f.value, f.getTracebackObject()), # type: ignore[arg-type] 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: else:
code = HTTPStatus.INTERNAL_SERVER_ERROR code = HTTPStatus.INTERNAL_SERVER_ERROR
msg = "Internal server error" msg = "Internal server error"