From 18e144fe088bda9e28697062cda62dca1e03724b Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 9 May 2018 19:55:03 +0100 Subject: [PATCH 1/9] Move RequestsMetrics to its own file This is useful in its own right, because server.py is full of stuff; but more importantly, I want to do some refactoring that will cause a circular reference as it is. --- synapse/http/request_metrics.py | 147 ++++++++++++++++++++++++++++++++ synapse/http/server.py | 128 +-------------------------- 2 files changed, 151 insertions(+), 124 deletions(-) create mode 100644 synapse/http/request_metrics.py diff --git a/synapse/http/request_metrics.py b/synapse/http/request_metrics.py new file mode 100644 index 000000000000..4a843a36a7f7 --- /dev/null +++ b/synapse/http/request_metrics.py @@ -0,0 +1,147 @@ +# -*- coding: utf-8 -*- +# Copyright 2014-2016 OpenMarket Ltd +# Copyright 2018 New Vector Ltd +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +import logging + +import synapse.metrics +from synapse.util.logcontext import LoggingContext + +logger = logging.getLogger(__name__) + +metrics = synapse.metrics.get_metrics_for("synapse.http.server") + +# total number of responses served, split by method/servlet/tag +response_count = metrics.register_counter( + "response_count", + labels=["method", "servlet", "tag"], + alternative_names=( + # the following are all deprecated aliases for the same metric + metrics.name_prefix + x for x in ( + "_requests", + "_response_time:count", + "_response_ru_utime:count", + "_response_ru_stime:count", + "_response_db_txn_count:count", + "_response_db_txn_duration:count", + ) + ) +) + +requests_counter = metrics.register_counter( + "requests_received", + labels=["method", "servlet", ], +) + +outgoing_responses_counter = metrics.register_counter( + "responses", + labels=["method", "code"], +) + +response_timer = metrics.register_counter( + "response_time_seconds", + labels=["method", "servlet", "tag"], + alternative_names=( + metrics.name_prefix + "_response_time:total", + ), +) + +response_ru_utime = metrics.register_counter( + "response_ru_utime_seconds", labels=["method", "servlet", "tag"], + alternative_names=( + metrics.name_prefix + "_response_ru_utime:total", + ), +) + +response_ru_stime = metrics.register_counter( + "response_ru_stime_seconds", labels=["method", "servlet", "tag"], + alternative_names=( + metrics.name_prefix + "_response_ru_stime:total", + ), +) + +response_db_txn_count = metrics.register_counter( + "response_db_txn_count", labels=["method", "servlet", "tag"], + alternative_names=( + metrics.name_prefix + "_response_db_txn_count:total", + ), +) + +# seconds spent waiting for db txns, excluding scheduling time, when processing +# this request +response_db_txn_duration = metrics.register_counter( + "response_db_txn_duration_seconds", labels=["method", "servlet", "tag"], + alternative_names=( + metrics.name_prefix + "_response_db_txn_duration:total", + ), +) + +# seconds spent waiting for a db connection, when processing this request +response_db_sched_duration = metrics.register_counter( + "response_db_sched_duration_seconds", labels=["method", "servlet", "tag"] +) + +# size in bytes of the response written +response_size = metrics.register_counter( + "response_size", labels=["method", "servlet", "tag"] +) + + +class RequestMetrics(object): + def start(self, clock, name): + self.start = clock.time_msec() + self.start_context = LoggingContext.current_context() + self.name = name + + def stop(self, clock, request): + context = LoggingContext.current_context() + + tag = "" + if context: + tag = context.tag + + if context != self.start_context: + logger.warn( + "Context have unexpectedly changed %r, %r", + context, self.start_context + ) + return + + response_count.inc(request.method, self.name, tag) + + response_timer.inc_by( + clock.time_msec() - self.start, request.method, + self.name, tag + ) + + ru_utime, ru_stime = context.get_resource_usage() + + response_ru_utime.inc_by( + ru_utime, request.method, self.name, tag + ) + response_ru_stime.inc_by( + ru_stime, request.method, self.name, tag + ) + response_db_txn_count.inc_by( + context.db_txn_count, request.method, self.name, tag + ) + response_db_txn_duration.inc_by( + context.db_txn_duration_ms / 1000., request.method, self.name, tag + ) + response_db_sched_duration.inc_by( + context.db_sched_duration_ms / 1000., request.method, self.name, tag + ) + + response_size.inc_by(request.sentLength, request.method, self.name, tag) diff --git a/synapse/http/server.py b/synapse/http/server.py index 55b9ad5251bd..37b26b908e78 100644 --- a/synapse/http/server.py +++ b/synapse/http/server.py @@ -18,6 +18,10 @@ from synapse.api.errors import ( cs_exception, SynapseError, CodeMessageException, UnrecognizedRequestError, Codes ) +from synapse.http.request_metrics import ( + RequestMetrics, requests_counter, + outgoing_responses_counter, +) from synapse.util.logcontext import LoggingContext, PreserveLoggingContext from synapse.util.caches import intern_dict from synapse.util.metrics import Measure @@ -41,82 +45,6 @@ logger = logging.getLogger(__name__) -metrics = synapse.metrics.get_metrics_for(__name__) - -# total number of responses served, split by method/servlet/tag -response_count = metrics.register_counter( - "response_count", - labels=["method", "servlet", "tag"], - alternative_names=( - # the following are all deprecated aliases for the same metric - metrics.name_prefix + x for x in ( - "_requests", - "_response_time:count", - "_response_ru_utime:count", - "_response_ru_stime:count", - "_response_db_txn_count:count", - "_response_db_txn_duration:count", - ) - ) -) - -requests_counter = metrics.register_counter( - "requests_received", - labels=["method", "servlet", ], -) - -outgoing_responses_counter = metrics.register_counter( - "responses", - labels=["method", "code"], -) - -response_timer = metrics.register_counter( - "response_time_seconds", - labels=["method", "servlet", "tag"], - alternative_names=( - metrics.name_prefix + "_response_time:total", - ), -) - -response_ru_utime = metrics.register_counter( - "response_ru_utime_seconds", labels=["method", "servlet", "tag"], - alternative_names=( - metrics.name_prefix + "_response_ru_utime:total", - ), -) - -response_ru_stime = metrics.register_counter( - "response_ru_stime_seconds", labels=["method", "servlet", "tag"], - alternative_names=( - metrics.name_prefix + "_response_ru_stime:total", - ), -) - -response_db_txn_count = metrics.register_counter( - "response_db_txn_count", labels=["method", "servlet", "tag"], - alternative_names=( - metrics.name_prefix + "_response_db_txn_count:total", - ), -) - -# seconds spent waiting for db txns, excluding scheduling time, when processing -# this request -response_db_txn_duration = metrics.register_counter( - "response_db_txn_duration_seconds", labels=["method", "servlet", "tag"], - alternative_names=( - metrics.name_prefix + "_response_db_txn_duration:total", - ), -) - -# seconds spent waiting for a db connection, when processing this request -response_db_sched_duration = metrics.register_counter( - "response_db_sched_duration_seconds", labels=["method", "servlet", "tag"] -) - -# size in bytes of the response written -response_size = metrics.register_counter( - "response_size", labels=["method", "servlet", "tag"] -) _next_request_id = 0 @@ -386,54 +314,6 @@ def _unrecognised_request_handler(request): raise UnrecognizedRequestError() -class RequestMetrics(object): - def start(self, clock, name): - self.start = clock.time_msec() - self.start_context = LoggingContext.current_context() - self.name = name - - def stop(self, clock, request): - context = LoggingContext.current_context() - - tag = "" - if context: - tag = context.tag - - if context != self.start_context: - logger.warn( - "Context have unexpectedly changed %r, %r", - context, self.start_context - ) - return - - response_count.inc(request.method, self.name, tag) - - response_timer.inc_by( - clock.time_msec() - self.start, request.method, - self.name, tag - ) - - ru_utime, ru_stime = context.get_resource_usage() - - response_ru_utime.inc_by( - ru_utime, request.method, self.name, tag - ) - response_ru_stime.inc_by( - ru_stime, request.method, self.name, tag - ) - response_db_txn_count.inc_by( - context.db_txn_count, request.method, self.name, tag - ) - response_db_txn_duration.inc_by( - context.db_txn_duration_ms / 1000., request.method, self.name, tag - ) - response_db_sched_duration.inc_by( - context.db_sched_duration_ms / 1000., request.method, self.name, tag - ) - - response_size.inc_by(request.sentLength, request.method, self.name, tag) - - class RootRedirect(resource.Resource): """Redirects the root '/' path to another path.""" From 8460e48d0639a7f575fd3e57dcd5cf263a6d6a19 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 9 May 2018 23:00:11 +0100 Subject: [PATCH 2/9] Move request_id management into SynapseRequest --- synapse/http/server.py | 31 ++++++++++++++++--------------- synapse/http/site.py | 9 +++++++++ 2 files changed, 25 insertions(+), 15 deletions(-) diff --git a/synapse/http/server.py b/synapse/http/server.py index 37b26b908e78..369f7bbdd1f8 100644 --- a/synapse/http/server.py +++ b/synapse/http/server.py @@ -46,38 +46,40 @@ logger = logging.getLogger(__name__) -_next_request_id = 0 - - def request_handler(include_metrics=False): """Decorator for ``wrap_request_handler``""" return lambda request_handler: wrap_request_handler(request_handler, include_metrics) def wrap_request_handler(request_handler, include_metrics=False): - """Wraps a method that acts as a request handler with the necessary logging - and exception handling. + """Wraps a request handler method with the necessary logging and exception + handling. - The method must have a signature of "handle_foo(self, request)". The - argument "self" must have "version_string" and "clock" attributes. The - argument "request" must be a twisted HTTP request. + The handler method must have a signature of "handle_foo(self, request)", + where "self" must have "version_string" and "clock" attributes (and + "request" must be a SynapseRequest). - The method must return a deferred. If the deferred succeeds we assume that + The handler must return a deferred. If the deferred succeeds we assume that a response has been sent. If the deferred fails with a SynapseError we use it to send a JSON response with the appropriate HTTP reponse code. If the deferred fails with any other type of error we send a 500 reponse. - We insert a unique request-id into the logging context for this request and - log the response and duration for this request. + As well as calling `request.processing` (which will log the response and + duration for this request), the wrapped request handler will insert the + request id into the logging context. """ @defer.inlineCallbacks def wrapped_request_handler(self, request): - global _next_request_id - request_id = "%s-%s" % (request.method, _next_request_id) - _next_request_id += 1 + """ + Args: + self: + request (synapse.http.site.SynapseRequest): + """ + request_id = request.get_request_id() with LoggingContext(request_id) as request_context: + request_context.request = request_id with Measure(self.clock, "wrapped_request_handler"): request_metrics = RequestMetrics() # we start the request metrics timer here with an initial stab @@ -87,7 +89,6 @@ def wrapped_request_handler(self, request): servlet_name = self.__class__.__name__ request_metrics.start(self.clock, name=servlet_name) - request_context.request = request_id with request.processing(): try: with PreserveLoggingContext(request_context): diff --git a/synapse/http/site.py b/synapse/http/site.py index c8b46e1af25f..6af276e69a6c 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -22,6 +22,8 @@ ACCESS_TOKEN_RE = re.compile(br'(\?.*access(_|%5[Ff])token=)[^&]*(.*)$') +_next_request_seq = 0 + class SynapseRequest(Request): def __init__(self, site, *args, **kw): @@ -30,6 +32,10 @@ def __init__(self, site, *args, **kw): self.authenticated_entity = None self.start_time = 0 + global _next_request_seq + self.request_seq = _next_request_seq + _next_request_seq += 1 + def __repr__(self): # We overwrite this so that we don't log ``access_token`` return '<%s at 0x%x method=%s uri=%s clientproto=%s site=%s>' % ( @@ -41,6 +47,9 @@ def __repr__(self): self.site.site_tag, ) + def get_request_id(self): + return "%s-%i" % (self.method, self.request_seq) + def get_redacted_uri(self): return ACCESS_TOKEN_RE.sub( br'\1\3', From 09b29f9c4a941ae5721b1f5e296156dfe92e3395 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 9 May 2018 23:03:11 +0100 Subject: [PATCH 3/9] Make RequestMetrics take a raw time rather than a clock ... which is going to make it easier to move around. --- synapse/http/request_metrics.py | 8 ++++---- synapse/http/server.py | 4 ++-- 2 files changed, 6 insertions(+), 6 deletions(-) diff --git a/synapse/http/request_metrics.py b/synapse/http/request_metrics.py index 4a843a36a7f7..4e8a5f5306a2 100644 --- a/synapse/http/request_metrics.py +++ b/synapse/http/request_metrics.py @@ -100,12 +100,12 @@ class RequestMetrics(object): - def start(self, clock, name): - self.start = clock.time_msec() + def start(self, time_msec, name): + self.start = time_msec self.start_context = LoggingContext.current_context() self.name = name - def stop(self, clock, request): + def stop(self, time_msec, request): context = LoggingContext.current_context() tag = "" @@ -122,7 +122,7 @@ def stop(self, clock, request): response_count.inc(request.method, self.name, tag) response_timer.inc_by( - clock.time_msec() - self.start, request.method, + time_msec - self.start, request.method, self.name, tag ) diff --git a/synapse/http/server.py b/synapse/http/server.py index 369f7bbdd1f8..b16c9c17f6cd 100644 --- a/synapse/http/server.py +++ b/synapse/http/server.py @@ -87,7 +87,7 @@ def wrapped_request_handler(self, request): # JsonResource (or a subclass), and JsonResource._async_render # will update it once it picks a servlet. servlet_name = self.__class__.__name__ - request_metrics.start(self.clock, name=servlet_name) + request_metrics.start(self.clock.time_msec(), name=servlet_name) with request.processing(): try: @@ -138,7 +138,7 @@ def wrapped_request_handler(self, request): finally: try: request_metrics.stop( - self.clock, request + self.clock.time_msec(), request ) except Exception as e: logger.warn("Failed to stop metrics: %r", e) From c6f730282c3a25468df0e624293aefd60cef7840 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 9 May 2018 23:05:14 +0100 Subject: [PATCH 4/9] Move RequestMetrics handling into SynapseRequest.processing() It fits quite nicely here, and opens the path to getting rid of the "include_metrics" mess. --- synapse/http/server.py | 19 ++++-------- synapse/http/site.py | 69 +++++++++++++++++++++++++++++++++++------- 2 files changed, 64 insertions(+), 24 deletions(-) diff --git a/synapse/http/server.py b/synapse/http/server.py index b16c9c17f6cd..8e5d1d58f5ec 100644 --- a/synapse/http/server.py +++ b/synapse/http/server.py @@ -19,7 +19,7 @@ cs_exception, SynapseError, CodeMessageException, UnrecognizedRequestError, Codes ) from synapse.http.request_metrics import ( - RequestMetrics, requests_counter, + requests_counter, outgoing_responses_counter, ) from synapse.util.logcontext import LoggingContext, PreserveLoggingContext @@ -81,19 +81,18 @@ def wrapped_request_handler(self, request): with LoggingContext(request_id) as request_context: request_context.request = request_id with Measure(self.clock, "wrapped_request_handler"): - request_metrics = RequestMetrics() # we start the request metrics timer here with an initial stab # at the servlet name. For most requests that name will be # JsonResource (or a subclass), and JsonResource._async_render # will update it once it picks a servlet. servlet_name = self.__class__.__name__ - request_metrics.start(self.clock.time_msec(), name=servlet_name) - - with request.processing(): + with request.processing(servlet_name): try: with PreserveLoggingContext(request_context): if include_metrics: - yield request_handler(self, request, request_metrics) + yield request_handler( + self, request, request.request_metrics, + ) else: requests_counter.inc(request.method, servlet_name) yield request_handler(self, request) @@ -135,13 +134,7 @@ def wrapped_request_handler(self, request): pretty_print=_request_user_agent_is_curl(request), version_string=self.version_string, ) - finally: - try: - request_metrics.stop( - self.clock.time_msec(), request - ) - except Exception as e: - logger.warn("Failed to stop metrics: %r", e) + return wrapped_request_handler diff --git a/synapse/http/site.py b/synapse/http/site.py index 6af276e69a6c..bfd9832aa05d 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -12,20 +12,38 @@ # See the License for the specific language governing permissions and # limitations under the License. -from synapse.util.logcontext import LoggingContext -from twisted.web.server import Site, Request - import contextlib import logging import re import time +from twisted.web.server import Site, Request + +from synapse.http.request_metrics import RequestMetrics +from synapse.util.logcontext import LoggingContext + +logger = logging.getLogger(__name__) + ACCESS_TOKEN_RE = re.compile(br'(\?.*access(_|%5[Ff])token=)[^&]*(.*)$') _next_request_seq = 0 class SynapseRequest(Request): + """Class which encapsulates an HTTP request to synapse. + + All of the requests processed in synapse are of this type. + + It extends twisted's twisted.web.server.Request, and adds: + * Unique request ID + * Redaction of access_token query-params in __repr__ + * Logging at start and end + * Metrics to record CPU, wallclock and DB time by endpoint. + + It provides a method `processing` which should be called by the Resource + which is handling the request, and returns a context manager. + + """ def __init__(self, site, *args, **kw): Request.__init__(self, *args, **kw) self.site = site @@ -59,7 +77,11 @@ def get_redacted_uri(self): def get_user_agent(self): return self.requestHeaders.getRawHeaders(b"User-Agent", [None])[-1] - def started_processing(self): + def _started_processing(self, servlet_name): + self.start_time = int(time.time() * 1000) + self.request_metrics = RequestMetrics() + self.request_metrics.start(self.start_time, name=servlet_name) + self.site.access_logger.info( "%s - %s - Received request: %s %s", self.getClientIP(), @@ -67,10 +89,8 @@ def started_processing(self): self.method, self.get_redacted_uri() ) - self.start_time = int(time.time() * 1000) - - def finished_processing(self): + def _finished_processing(self): try: context = LoggingContext.current_context() ru_utime, ru_stime = context.get_resource_usage() @@ -81,6 +101,8 @@ def finished_processing(self): ru_utime, ru_stime = (0, 0) db_txn_count, db_txn_duration_ms = (0, 0) + end_time = int(time.time() * 1000) + self.site.access_logger.info( "%s - %s - {%s}" " Processed request: %dms (%dms, %dms) (%dms/%dms/%d)" @@ -88,7 +110,7 @@ def finished_processing(self): self.getClientIP(), self.site.site_tag, self.authenticated_entity, - int(time.time() * 1000) - self.start_time, + end_time - self.start_time, int(ru_utime * 1000), int(ru_stime * 1000), db_sched_duration_ms, @@ -102,11 +124,36 @@ def finished_processing(self): self.get_user_agent(), ) + try: + self.request_metrics.stop(end_time, self) + except Exception as e: + logger.warn("Failed to stop metrics: %r", e) + @contextlib.contextmanager - def processing(self): - self.started_processing() + def processing(self, servlet_name): + """Record the fact that we are processing this request. + + Returns a context manager; the correct way to use this is: + + @defer.inlineCallbacks + def handle_request(request): + with request.processing("FooServlet"): + yield really_handle_the_request() + + This will log the request's arrival. Once the context manager is + closed, the completion of the request will be logged, and the various + metrics will be updated. + + Args: + servlet_name (str): the name of the servlet which will be + processing this request. This is used in the metrics. + + It is possible to update this afterwards by updating + self.request_metrics.servlet_name. + """ + self._started_processing(servlet_name) yield - self.finished_processing() + self._finished_processing() class XForwardedForRequest(SynapseRequest): From b8700dd7d0482813beb9c780b411de5108ae078a Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 9 May 2018 18:03:04 +0100 Subject: [PATCH 5/9] Bump requests_counter in wrapped_request_handler less magic --- synapse/http/server.py | 15 +++++++++++---- 1 file changed, 11 insertions(+), 4 deletions(-) diff --git a/synapse/http/server.py b/synapse/http/server.py index 8e5d1d58f5ec..1d05b538732d 100644 --- a/synapse/http/server.py +++ b/synapse/http/server.py @@ -90,12 +90,20 @@ def wrapped_request_handler(self, request): try: with PreserveLoggingContext(request_context): if include_metrics: - yield request_handler( + d = request_handler( self, request, request.request_metrics, ) else: - requests_counter.inc(request.method, servlet_name) - yield request_handler(self, request) + d = request_handler(self, request) + + # record the arrival of the request *after* + # dispatching to the handler, so that the handler + # can update the servlet name in the request + # metrics + requests_counter.inc(request.method, + request.request_metrics.name) + yield d + except CodeMessageException as e: code = e.code if isinstance(e, SynapseError): @@ -220,7 +228,6 @@ def _async_render(self, request, request_metrics): servlet_classname = "%r" % callback request_metrics.name = servlet_classname - requests_counter.inc(request.method, servlet_classname) # Now trigger the callback. If it returns a response, we send it # here. If it throws an exception, that is handled by the wrapper From 49e5a613f1ac53498b31150f78332fc64932e61b Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 9 May 2018 23:44:22 +0100 Subject: [PATCH 6/9] Move outgoing_responses_counter handling to RequestMetrics it's much neater there. --- synapse/http/request_metrics.py | 2 ++ synapse/http/server.py | 4 ---- 2 files changed, 2 insertions(+), 4 deletions(-) diff --git a/synapse/http/request_metrics.py b/synapse/http/request_metrics.py index 4e8a5f5306a2..8c850bf23f70 100644 --- a/synapse/http/request_metrics.py +++ b/synapse/http/request_metrics.py @@ -119,6 +119,8 @@ def stop(self, time_msec, request): ) return + outgoing_responses_counter.inc(request.method, str(request.code)) + response_count.inc(request.method, self.name, tag) response_timer.inc_by( diff --git a/synapse/http/server.py b/synapse/http/server.py index 1d05b538732d..200b2c4837aa 100644 --- a/synapse/http/server.py +++ b/synapse/http/server.py @@ -20,7 +20,6 @@ ) from synapse.http.request_metrics import ( requests_counter, - outgoing_responses_counter, ) from synapse.util.logcontext import LoggingContext, PreserveLoggingContext from synapse.util.caches import intern_dict @@ -112,7 +111,6 @@ def wrapped_request_handler(self, request): ) else: logger.exception(e) - outgoing_responses_counter.inc(request.method, str(code)) respond_with_json( request, code, cs_exception(e), send_cors=True, pretty_print=_request_user_agent_is_curl(request), @@ -274,8 +272,6 @@ def _get_handler_for_request(self, request): def _send_response(self, request, code, response_json_object, response_code_message=None): - outgoing_responses_counter.inc(request.method, str(code)) - # TODO: Only enable CORS for the requests that need it. respond_with_json( request, code, response_json_object, From 9589a1925e944360c68f7eb8a65f8ba94ec9bb84 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 9 May 2018 23:49:29 +0100 Subject: [PATCH 7/9] Remove include_metrics param The metrics are now available via the request, so this is redundant and can go away at last. --- synapse/http/server.py | 24 +++++++----------------- 1 file changed, 7 insertions(+), 17 deletions(-) diff --git a/synapse/http/server.py b/synapse/http/server.py index 200b2c4837aa..9598969de888 100644 --- a/synapse/http/server.py +++ b/synapse/http/server.py @@ -45,12 +45,12 @@ logger = logging.getLogger(__name__) -def request_handler(include_metrics=False): +def request_handler(): """Decorator for ``wrap_request_handler``""" - return lambda request_handler: wrap_request_handler(request_handler, include_metrics) + return wrap_request_handler -def wrap_request_handler(request_handler, include_metrics=False): +def wrap_request_handler(request_handler): """Wraps a request handler method with the necessary logging and exception handling. @@ -88,12 +88,7 @@ def wrapped_request_handler(self, request): with request.processing(servlet_name): try: with PreserveLoggingContext(request_context): - if include_metrics: - d = request_handler( - self, request, request.request_metrics, - ) - else: - d = request_handler(self, request) + d = request_handler(self, request) # record the arrival of the request *after* # dispatching to the handler, so that the handler @@ -206,13 +201,9 @@ def render(self, request): self._async_render(request) return server.NOT_DONE_YET - # Disable metric reporting because _async_render does its own metrics. - # It does its own metric reporting because _async_render dispatches to - # a callback and it's the class name of that callback we want to report - # against rather than the JsonResource itself. - @request_handler(include_metrics=True) + @request_handler() @defer.inlineCallbacks - def _async_render(self, request, request_metrics): + def _async_render(self, request): """ This gets called from render() every time someone sends us a request. This checks if anyone has registered a callback for that method and path. @@ -224,8 +215,7 @@ def _async_render(self, request, request_metrics): servlet_classname = servlet_instance.__class__.__name__ else: servlet_classname = "%r" % callback - - request_metrics.name = servlet_classname + request.request_metrics.name = servlet_classname # Now trigger the callback. If it returns a response, we send it # here. If it throws an exception, that is handled by the wrapper From 09f570b9357d40764a0716f7e287fa4dde44610a Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Thu, 10 May 2018 11:59:51 +0100 Subject: [PATCH 8/9] Factor wrap_request_handler_with_logging out of wrap_request_handler ... so that it can be used on non-JSON endpoints --- synapse/http/server.py | 120 ++++++++++++++++++++++------------------- 1 file changed, 66 insertions(+), 54 deletions(-) diff --git a/synapse/http/server.py b/synapse/http/server.py index 9598969de888..fd58e65c4bd3 100644 --- a/synapse/http/server.py +++ b/synapse/http/server.py @@ -50,9 +50,10 @@ def request_handler(): return wrap_request_handler -def wrap_request_handler(request_handler): - """Wraps a request handler method with the necessary logging and exception - handling. +def wrap_request_handler(h): + """Wraps a request handler method with exception handling. + + Also adds logging as per wrap_request_handler_with_logging. The handler method must have a signature of "handle_foo(self, request)", where "self" must have "version_string" and "clock" attributes (and @@ -62,12 +63,63 @@ def wrap_request_handler(request_handler): a response has been sent. If the deferred fails with a SynapseError we use it to send a JSON response with the appropriate HTTP reponse code. If the deferred fails with any other type of error we send a 500 reponse. + """ + + @defer.inlineCallbacks + def wrapped_request_handler(self, request): + try: + yield h(self, request) + except CodeMessageException as e: + code = e.code + if isinstance(e, SynapseError): + logger.info( + "%s SynapseError: %s - %s", request, code, e.msg + ) + else: + logger.exception(e) + respond_with_json( + request, code, cs_exception(e), send_cors=True, + pretty_print=_request_user_agent_is_curl(request), + version_string=self.version_string, + ) + + except Exception: + # failure.Failure() fishes the original Failure out + # of our stack, and thus gives us a sensible stack + # trace. + f = failure.Failure() + logger.error( + "Failed handle request via %r: %r: %s", + h, + request, + f.getTraceback().rstrip(), + ) + respond_with_json( + request, + 500, + { + "error": "Internal server error", + "errcode": Codes.UNKNOWN, + }, + send_cors=True, + pretty_print=_request_user_agent_is_curl(request), + version_string=self.version_string, + ) + + return wrap_request_handler_with_logging(wrapped_request_handler) + + +def wrap_request_handler_with_logging(h): + """Wraps a request handler to provide logging and metrics + + The handler method must have a signature of "handle_foo(self, request)", + where "self" must have a "clock" attribute (and "request" must be a + SynapseRequest). As well as calling `request.processing` (which will log the response and duration for this request), the wrapped request handler will insert the request id into the logging context. """ - @defer.inlineCallbacks def wrapped_request_handler(self, request): """ @@ -86,56 +138,16 @@ def wrapped_request_handler(self, request): # will update it once it picks a servlet. servlet_name = self.__class__.__name__ with request.processing(servlet_name): - try: - with PreserveLoggingContext(request_context): - d = request_handler(self, request) - - # record the arrival of the request *after* - # dispatching to the handler, so that the handler - # can update the servlet name in the request - # metrics - requests_counter.inc(request.method, - request.request_metrics.name) - yield d - - except CodeMessageException as e: - code = e.code - if isinstance(e, SynapseError): - logger.info( - "%s SynapseError: %s - %s", request, code, e.msg - ) - else: - logger.exception(e) - respond_with_json( - request, code, cs_exception(e), send_cors=True, - pretty_print=_request_user_agent_is_curl(request), - version_string=self.version_string, - ) - except Exception: - # failure.Failure() fishes the original Failure out - # of our stack, and thus gives us a sensible stack - # trace. - f = failure.Failure() - logger.error( - "Failed handle request %s.%s on %r: %r: %s", - request_handler.__module__, - request_handler.__name__, - self, - request, - f.getTraceback().rstrip(), - ) - respond_with_json( - request, - 500, - { - "error": "Internal server error", - "errcode": Codes.UNKNOWN, - }, - send_cors=True, - pretty_print=_request_user_agent_is_curl(request), - version_string=self.version_string, - ) - + with PreserveLoggingContext(request_context): + d = h(self, request) + + # record the arrival of the request *after* + # dispatching to the handler, so that the handler + # can update the servlet name in the request + # metrics + requests_counter.inc(request.method, + request.request_metrics.name) + yield d return wrapped_request_handler From 645cb4bf06deee1c4c10ecc3d7df2c914168f19a Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Thu, 10 May 2018 12:10:27 +0100 Subject: [PATCH 9/9] Remove redundant request_handler decorator This is needless complexity; we might as well use the wrapper directly. Also rename wrap_request_handler->wrap_json_request_handler. --- synapse/http/additional_resource.py | 4 ++-- synapse/http/server.py | 9 ++------ synapse/rest/key/v2/remote_key_resource.py | 8 ++++--- synapse/rest/media/v1/download_resource.py | 16 +++++++------ synapse/rest/media/v1/preview_url_resource.py | 5 ++-- synapse/rest/media/v1/thumbnail_resource.py | 23 +++++++++++-------- synapse/rest/media/v1/upload_resource.py | 15 ++++++------ 7 files changed, 42 insertions(+), 38 deletions(-) diff --git a/synapse/http/additional_resource.py b/synapse/http/additional_resource.py index 343e932cb1b7..d9e7f5dfb7db 100644 --- a/synapse/http/additional_resource.py +++ b/synapse/http/additional_resource.py @@ -13,7 +13,7 @@ # See the License for the specific language governing permissions and # limitations under the License. -from synapse.http.server import wrap_request_handler +from synapse.http.server import wrap_json_request_handler from twisted.web.resource import Resource from twisted.web.server import NOT_DONE_YET @@ -50,6 +50,6 @@ def render(self, request): self._async_render(request) return NOT_DONE_YET - @wrap_request_handler + @wrap_json_request_handler def _async_render(self, request): return self._handler(request) diff --git a/synapse/http/server.py b/synapse/http/server.py index fd58e65c4bd3..f29e36f490a6 100644 --- a/synapse/http/server.py +++ b/synapse/http/server.py @@ -45,12 +45,7 @@ logger = logging.getLogger(__name__) -def request_handler(): - """Decorator for ``wrap_request_handler``""" - return wrap_request_handler - - -def wrap_request_handler(h): +def wrap_json_request_handler(h): """Wraps a request handler method with exception handling. Also adds logging as per wrap_request_handler_with_logging. @@ -213,7 +208,7 @@ def render(self, request): self._async_render(request) return server.NOT_DONE_YET - @request_handler() + @wrap_json_request_handler @defer.inlineCallbacks def _async_render(self, request): """ This gets called from render() every time someone sends us a request. diff --git a/synapse/rest/key/v2/remote_key_resource.py b/synapse/rest/key/v2/remote_key_resource.py index 17e6079cba71..17b3077926ce 100644 --- a/synapse/rest/key/v2/remote_key_resource.py +++ b/synapse/rest/key/v2/remote_key_resource.py @@ -12,7 +12,9 @@ # See the License for the specific language governing permissions and # limitations under the License. -from synapse.http.server import request_handler, respond_with_json_bytes +from synapse.http.server import ( + respond_with_json_bytes, wrap_json_request_handler, +) from synapse.http.servlet import parse_integer, parse_json_object_from_request from synapse.api.errors import SynapseError, Codes from synapse.crypto.keyring import KeyLookupError @@ -99,7 +101,7 @@ def render_GET(self, request): self.async_render_GET(request) return NOT_DONE_YET - @request_handler() + @wrap_json_request_handler @defer.inlineCallbacks def async_render_GET(self, request): if len(request.postpath) == 1: @@ -124,7 +126,7 @@ def render_POST(self, request): self.async_render_POST(request) return NOT_DONE_YET - @request_handler() + @wrap_json_request_handler @defer.inlineCallbacks def async_render_POST(self, request): content = parse_json_object_from_request(request) diff --git a/synapse/rest/media/v1/download_resource.py b/synapse/rest/media/v1/download_resource.py index fe7e17596fcd..3fc3f64d6293 100644 --- a/synapse/rest/media/v1/download_resource.py +++ b/synapse/rest/media/v1/download_resource.py @@ -12,16 +12,18 @@ # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. # See the License for the specific language governing permissions and # limitations under the License. -import synapse.http.servlet +import logging -from ._base import parse_media_id, respond_404 +from twisted.internet import defer from twisted.web.resource import Resource -from synapse.http.server import request_handler, set_cors_headers - from twisted.web.server import NOT_DONE_YET -from twisted.internet import defer -import logging +from synapse.http.server import ( + set_cors_headers, + wrap_json_request_handler, +) +import synapse.http.servlet +from ._base import parse_media_id, respond_404 logger = logging.getLogger(__name__) @@ -43,7 +45,7 @@ def render_GET(self, request): self._async_render_GET(request) return NOT_DONE_YET - @request_handler() + @wrap_json_request_handler @defer.inlineCallbacks def _async_render_GET(self, request): set_cors_headers(request) diff --git a/synapse/rest/media/v1/preview_url_resource.py b/synapse/rest/media/v1/preview_url_resource.py index 9290d7946fc3..6b089689b4e8 100644 --- a/synapse/rest/media/v1/preview_url_resource.py +++ b/synapse/rest/media/v1/preview_url_resource.py @@ -40,8 +40,9 @@ from synapse.util.caches.expiringcache import ExpiringCache from synapse.http.client import SpiderHttpClient from synapse.http.server import ( - request_handler, respond_with_json_bytes, + respond_with_json_bytes, respond_with_json, + wrap_json_request_handler, ) from synapse.util.async import ObservableDeferred from synapse.util.stringutils import is_ascii @@ -90,7 +91,7 @@ def render_GET(self, request): self._async_render_GET(request) return NOT_DONE_YET - @request_handler() + @wrap_json_request_handler @defer.inlineCallbacks def _async_render_GET(self, request): diff --git a/synapse/rest/media/v1/thumbnail_resource.py b/synapse/rest/media/v1/thumbnail_resource.py index 58ada49711cc..6c12d79f561f 100644 --- a/synapse/rest/media/v1/thumbnail_resource.py +++ b/synapse/rest/media/v1/thumbnail_resource.py @@ -14,18 +14,21 @@ # limitations under the License. -from ._base import ( - parse_media_id, respond_404, respond_with_file, FileInfo, - respond_with_responder, -) -from twisted.web.resource import Resource -from synapse.http.servlet import parse_string, parse_integer -from synapse.http.server import request_handler, set_cors_headers +import logging -from twisted.web.server import NOT_DONE_YET from twisted.internet import defer +from twisted.web.resource import Resource +from twisted.web.server import NOT_DONE_YET -import logging +from synapse.http.server import ( + set_cors_headers, + wrap_json_request_handler, +) +from synapse.http.servlet import parse_integer, parse_string +from ._base import ( + FileInfo, parse_media_id, respond_404, respond_with_file, + respond_with_responder, +) logger = logging.getLogger(__name__) @@ -48,7 +51,7 @@ def render_GET(self, request): self._async_render_GET(request) return NOT_DONE_YET - @request_handler() + @wrap_json_request_handler @defer.inlineCallbacks def _async_render_GET(self, request): set_cors_headers(request) diff --git a/synapse/rest/media/v1/upload_resource.py b/synapse/rest/media/v1/upload_resource.py index a31e75cb4664..7d01c57fd132 100644 --- a/synapse/rest/media/v1/upload_resource.py +++ b/synapse/rest/media/v1/upload_resource.py @@ -13,16 +13,17 @@ # See the License for the specific language governing permissions and # limitations under the License. -from synapse.http.server import respond_with_json, request_handler - -from synapse.api.errors import SynapseError +import logging -from twisted.web.server import NOT_DONE_YET from twisted.internet import defer - from twisted.web.resource import Resource +from twisted.web.server import NOT_DONE_YET -import logging +from synapse.api.errors import SynapseError +from synapse.http.server import ( + respond_with_json, + wrap_json_request_handler, +) logger = logging.getLogger(__name__) @@ -51,7 +52,7 @@ def render_OPTIONS(self, request): respond_with_json(request, 200, {}, send_cors=True) return NOT_DONE_YET - @request_handler() + @wrap_json_request_handler @defer.inlineCallbacks def _async_render_POST(self, request): requester = yield self.auth.get_user_by_req(request)