diff --git a/synapse/http/client.py b/synapse/http/client.py
index 155b7460d4..8aeb70cdec 100644
--- a/synapse/http/client.py
+++ b/synapse/http/client.py
@@ -284,8 +284,7 @@ class SimpleHttpClient(object):
ip_blacklist=self._ip_blacklist,
)
- @defer.inlineCallbacks
- def request(self, method, uri, data=None, headers=None):
+ async def request(self, method, uri, data=None, headers=None):
"""
Args:
method (str): HTTP method to use.
@@ -298,7 +297,7 @@ class SimpleHttpClient(object):
outgoing_requests_counter.labels(method).inc()
# log request but strip `access_token` (AS requests for example include this)
- logger.info("Sending request %s %s", method, redact_uri(uri))
+ logger.debug("Sending request %s %s", method, redact_uri(uri))
with start_active_span(
"outgoing-client-request",
@@ -330,7 +329,7 @@ class SimpleHttpClient(object):
self.hs.get_reactor(),
cancelled_to_request_timed_out_error,
)
- response = yield make_deferred_yieldable(request_deferred)
+ response = await make_deferred_yieldable(request_deferred)
incoming_responses_counter.labels(method, response.code).inc()
logger.info(
@@ -353,8 +352,7 @@ class SimpleHttpClient(object):
set_tag("error_reason", e.args[0])
raise
- @defer.inlineCallbacks
- def post_urlencoded_get_json(self, uri, args={}, headers=None):
+ async def post_urlencoded_get_json(self, uri, args={}, headers=None):
"""
Args:
uri (str):
@@ -363,7 +361,7 @@ class SimpleHttpClient(object):
header name to a list of values for that header
Returns:
- Deferred[object]: parsed json
+ object: parsed json
Raises:
HttpResponseException: On a non-2xx HTTP response.
@@ -386,11 +384,11 @@ class SimpleHttpClient(object):
if headers:
actual_headers.update(headers)
- response = yield self.request(
+ response = await self.request(
"POST", uri, headers=Headers(actual_headers), data=query_bytes
)
- body = yield make_deferred_yieldable(readBody(response))
+ body = await make_deferred_yieldable(readBody(response))
if 200 <= response.code < 300:
return json.loads(body.decode("utf-8"))
@@ -399,8 +397,7 @@ class SimpleHttpClient(object):
response.code, response.phrase.decode("ascii", errors="replace"), body
)
- @defer.inlineCallbacks
- def post_json_get_json(self, uri, post_json, headers=None):
+ async def post_json_get_json(self, uri, post_json, headers=None):
"""
Args:
@@ -410,7 +407,7 @@ class SimpleHttpClient(object):
header name to a list of values for that header
Returns:
- Deferred[object]: parsed json
+ object: parsed json
Raises:
HttpResponseException: On a non-2xx HTTP response.
@@ -429,11 +426,11 @@ class SimpleHttpClient(object):
if headers:
actual_headers.update(headers)
- response = yield self.request(
+ response = await self.request(
"POST", uri, headers=Headers(actual_headers), data=json_str
)
- body = yield make_deferred_yieldable(readBody(response))
+ body = await make_deferred_yieldable(readBody(response))
if 200 <= response.code < 300:
return json.loads(body.decode("utf-8"))
@@ -442,8 +439,7 @@ class SimpleHttpClient(object):
response.code, response.phrase.decode("ascii", errors="replace"), body
)
- @defer.inlineCallbacks
- def get_json(self, uri, args={}, headers=None):
+ async def get_json(self, uri, args={}, headers=None):
""" Gets some json from the given URI.
Args:
@@ -455,7 +451,7 @@ class SimpleHttpClient(object):
headers (dict[str|bytes, List[str|bytes]]|None): If not None, a map from
header name to a list of values for that header
Returns:
- Deferred: Succeeds when we get *any* 2xx HTTP response, with the
+ Succeeds when we get *any* 2xx HTTP response, with the
HTTP body as JSON.
Raises:
HttpResponseException On a non-2xx HTTP response.
@@ -466,11 +462,10 @@ class SimpleHttpClient(object):
if headers:
actual_headers.update(headers)
- body = yield self.get_raw(uri, args, headers=headers)
+ body = await self.get_raw(uri, args, headers=headers)
return json.loads(body.decode("utf-8"))
- @defer.inlineCallbacks
- def put_json(self, uri, json_body, args={}, headers=None):
+ async def put_json(self, uri, json_body, args={}, headers=None):
""" Puts some json to the given URI.
Args:
@@ -483,7 +478,7 @@ class SimpleHttpClient(object):
headers (dict[str|bytes, List[str|bytes]]|None): If not None, a map from
header name to a list of values for that header
Returns:
- Deferred: Succeeds when we get *any* 2xx HTTP response, with the
+ Succeeds when we get *any* 2xx HTTP response, with the
HTTP body as JSON.
Raises:
HttpResponseException On a non-2xx HTTP response.
@@ -504,11 +499,11 @@ class SimpleHttpClient(object):
if headers:
actual_headers.update(headers)
- response = yield self.request(
+ response = await self.request(
"PUT", uri, headers=Headers(actual_headers), data=json_str
)
- body = yield make_deferred_yieldable(readBody(response))
+ body = await make_deferred_yieldable(readBody(response))
if 200 <= response.code < 300:
return json.loads(body.decode("utf-8"))
@@ -517,8 +512,7 @@ class SimpleHttpClient(object):
response.code, response.phrase.decode("ascii", errors="replace"), body
)
- @defer.inlineCallbacks
- def get_raw(self, uri, args={}, headers=None):
+ async def get_raw(self, uri, args={}, headers=None):
""" Gets raw text from the given URI.
Args:
@@ -530,7 +524,7 @@ class SimpleHttpClient(object):
headers (dict[str|bytes, List[str|bytes]]|None): If not None, a map from
header name to a list of values for that header
Returns:
- Deferred: Succeeds when we get *any* 2xx HTTP response, with the
+ Succeeds when we get *any* 2xx HTTP response, with the
HTTP body as bytes.
Raises:
HttpResponseException on a non-2xx HTTP response.
@@ -543,9 +537,9 @@ class SimpleHttpClient(object):
if headers:
actual_headers.update(headers)
- response = yield self.request("GET", uri, headers=Headers(actual_headers))
+ response = await self.request("GET", uri, headers=Headers(actual_headers))
- body = yield make_deferred_yieldable(readBody(response))
+ body = await make_deferred_yieldable(readBody(response))
if 200 <= response.code < 300:
return body
@@ -557,8 +551,7 @@ class SimpleHttpClient(object):
# XXX: FIXME: This is horribly copy-pasted from matrixfederationclient.
# The two should be factored out.
- @defer.inlineCallbacks
- def get_file(self, url, output_stream, max_size=None, headers=None):
+ async def get_file(self, url, output_stream, max_size=None, headers=None):
"""GETs a file from a given URL
Args:
url (str): The URL to GET
@@ -574,7 +567,7 @@ class SimpleHttpClient(object):
if headers:
actual_headers.update(headers)
- response = yield self.request("GET", url, headers=Headers(actual_headers))
+ response = await self.request("GET", url, headers=Headers(actual_headers))
resp_headers = dict(response.headers.getAllRawHeaders())
@@ -598,7 +591,7 @@ class SimpleHttpClient(object):
# straight back in again
try:
- length = yield make_deferred_yieldable(
+ length = await make_deferred_yieldable(
_readBodyToFile(response, output_stream, max_size)
)
except SynapseError:
diff --git a/synapse/http/federation/matrix_federation_agent.py b/synapse/http/federation/matrix_federation_agent.py
index 0c02648015..369bf9c2fc 100644
--- a/synapse/http/federation/matrix_federation_agent.py
+++ b/synapse/http/federation/matrix_federation_agent.py
@@ -247,7 +247,7 @@ class MatrixHostnameEndpoint(object):
port = server.port
try:
- logger.info("Connecting to %s:%i", host.decode("ascii"), port)
+ logger.debug("Connecting to %s:%i", host.decode("ascii"), port)
endpoint = HostnameEndpoint(self._reactor, host, port)
if self._tls_options:
endpoint = wrapClientTLS(self._tls_options, endpoint)
diff --git a/synapse/http/matrixfederationclient.py b/synapse/http/matrixfederationclient.py
index 2a6373937a..738be43f46 100644
--- a/synapse/http/matrixfederationclient.py
+++ b/synapse/http/matrixfederationclient.py
@@ -29,10 +29,11 @@ from zope.interface import implementer
from twisted.internet import defer, protocol
from twisted.internet.error import DNSLookupError
-from twisted.internet.interfaces import IReactorPluggableNameResolver
+from twisted.internet.interfaces import IReactorPluggableNameResolver, IReactorTime
from twisted.internet.task import _EPSILON, Cooperator
from twisted.web._newclient import ResponseDone
from twisted.web.http_headers import Headers
+from twisted.web.iweb import IResponse
import synapse.metrics
import synapse.util.retryutils
@@ -74,7 +75,7 @@ MAXINT = sys.maxsize
_next_id = 1
-@attr.s
+@attr.s(frozen=True)
class MatrixFederationRequest(object):
method = attr.ib()
"""HTTP method
@@ -110,26 +111,52 @@ class MatrixFederationRequest(object):
:type: str|None
"""
+ uri = attr.ib(init=False, type=bytes)
+ """The URI of this request
+ """
+
def __attrs_post_init__(self):
global _next_id
- self.txn_id = "%s-O-%s" % (self.method, _next_id)
+ txn_id = "%s-O-%s" % (self.method, _next_id)
_next_id = (_next_id + 1) % (MAXINT - 1)
+ object.__setattr__(self, "txn_id", txn_id)
+
+ destination_bytes = self.destination.encode("ascii")
+ path_bytes = self.path.encode("ascii")
+ if self.query:
+ query_bytes = encode_query_args(self.query)
+ else:
+ query_bytes = b""
+
+ # The object is frozen so we can pre-compute this.
+ uri = urllib.parse.urlunparse(
+ (b"matrix", destination_bytes, path_bytes, None, query_bytes, b"")
+ )
+ object.__setattr__(self, "uri", uri)
+
def get_json(self):
if self.json_callback:
return self.json_callback()
return self.json
-async def _handle_json_response(reactor, timeout_sec, request, response):
+async def _handle_json_response(
+ reactor: IReactorTime,
+ timeout_sec: float,
+ request: MatrixFederationRequest,
+ response: IResponse,
+ start_ms: int,
+):
"""
Reads the JSON body of a response, with a timeout
Args:
- reactor (IReactor): twisted reactor, for the timeout
- timeout_sec (float): number of seconds to wait for response to complete
- request (MatrixFederationRequest): the request that triggered the response
- response (IResponse): response to the request
+ reactor: twisted reactor, for the timeout
+ timeout_sec: number of seconds to wait for response to complete
+ request: the request that triggered the response
+ response: response to the request
+ start_ms: Timestamp when request was made
Returns:
dict: parsed JSON response
@@ -143,23 +170,35 @@ async def _handle_json_response(reactor, timeout_sec, request, response):
body = await make_deferred_yieldable(d)
except TimeoutError as e:
logger.warning(
- "{%s} [%s] Timed out reading response", request.txn_id, request.destination,
+ "{%s} [%s] Timed out reading response - %s %s",
+ request.txn_id,
+ request.destination,
+ request.method,
+ request.uri.decode("ascii"),
)
raise RequestSendFailed(e, can_retry=True) from e
except Exception as e:
logger.warning(
- "{%s} [%s] Error reading response: %s",
+ "{%s} [%s] Error reading response %s %s: %s",
request.txn_id,
request.destination,
+ request.method,
+ request.uri.decode("ascii"),
e,
)
raise
+
+ time_taken_secs = reactor.seconds() - start_ms / 1000
+
logger.info(
- "{%s} [%s] Completed: %d %s",
+ "{%s} [%s] Completed request: %d %s in %.2f secs - %s %s",
request.txn_id,
request.destination,
response.code,
response.phrase.decode("ascii", errors="replace"),
+ time_taken_secs,
+ request.method,
+ request.uri.decode("ascii"),
)
return body
@@ -261,7 +300,9 @@ class MatrixFederationHttpClient(object):
# 'M_UNRECOGNIZED' which some endpoints can return when omitting a
# trailing slash on Synapse <= v0.99.3.
logger.info("Retrying request with trailing slash")
- request.path += "/"
+
+ # Request is frozen so we create a new instance
+ request = attr.evolve(request, path=request.path + "/")
response = await self._send_request(request, **send_request_args)
@@ -373,9 +414,7 @@ class MatrixFederationHttpClient(object):
else:
retries_left = MAX_SHORT_RETRIES
- url_bytes = urllib.parse.urlunparse(
- (b"matrix", destination_bytes, path_bytes, None, query_bytes, b"")
- )
+ url_bytes = request.uri
url_str = url_bytes.decode("ascii")
url_to_sign_bytes = urllib.parse.urlunparse(
@@ -402,7 +441,7 @@ class MatrixFederationHttpClient(object):
headers_dict[b"Authorization"] = auth_headers
- logger.info(
+ logger.debug(
"{%s} [%s] Sending request: %s %s; timeout %fs",
request.txn_id,
request.destination,
@@ -436,7 +475,6 @@ class MatrixFederationHttpClient(object):
except DNSLookupError as e:
raise RequestSendFailed(e, can_retry=retry_on_dns_fail) from e
except Exception as e:
- logger.info("Failed to send request: %s", e)
raise RequestSendFailed(e, can_retry=True) from e
incoming_responses_counter.labels(
@@ -496,7 +534,7 @@ class MatrixFederationHttpClient(object):
break
except RequestSendFailed as e:
- logger.warning(
+ logger.info(
"{%s} [%s] Request failed: %s %s: %s",
request.txn_id,
request.destination,
@@ -654,6 +692,8 @@ class MatrixFederationHttpClient(object):
json=data,
)
+ start_ms = self.clock.time_msec()
+
response = await self._send_request_with_optional_trailing_slash(
request,
try_trailing_slash_on_400,
@@ -664,7 +704,7 @@ class MatrixFederationHttpClient(object):
)
body = await _handle_json_response(
- self.reactor, self.default_timeout, request, response
+ self.reactor, self.default_timeout, request, response, start_ms
)
return body
@@ -720,6 +760,8 @@ class MatrixFederationHttpClient(object):
method="POST", destination=destination, path=path, query=args, json=data
)
+ start_ms = self.clock.time_msec()
+
response = await self._send_request(
request,
long_retries=long_retries,
@@ -733,7 +775,7 @@ class MatrixFederationHttpClient(object):
_sec_timeout = self.default_timeout
body = await _handle_json_response(
- self.reactor, _sec_timeout, request, response
+ self.reactor, _sec_timeout, request, response, start_ms,
)
return body
@@ -786,6 +828,8 @@ class MatrixFederationHttpClient(object):
method="GET", destination=destination, path=path, query=args
)
+ start_ms = self.clock.time_msec()
+
response = await self._send_request_with_optional_trailing_slash(
request,
try_trailing_slash_on_400,
@@ -796,7 +840,7 @@ class MatrixFederationHttpClient(object):
)
body = await _handle_json_response(
- self.reactor, self.default_timeout, request, response
+ self.reactor, self.default_timeout, request, response, start_ms
)
return body
@@ -846,6 +890,8 @@ class MatrixFederationHttpClient(object):
method="DELETE", destination=destination, path=path, query=args
)
+ start_ms = self.clock.time_msec()
+
response = await self._send_request(
request,
long_retries=long_retries,
@@ -854,7 +900,7 @@ class MatrixFederationHttpClient(object):
)
body = await _handle_json_response(
- self.reactor, self.default_timeout, request, response
+ self.reactor, self.default_timeout, request, response, start_ms
)
return body
@@ -914,12 +960,14 @@ class MatrixFederationHttpClient(object):
)
raise
logger.info(
- "{%s} [%s] Completed: %d %s [%d bytes]",
+ "{%s} [%s] Completed: %d %s [%d bytes] %s %s",
request.txn_id,
request.destination,
response.code,
response.phrase.decode("ascii", errors="replace"),
length,
+ request.method,
+ request.uri.decode("ascii"),
)
return (length, headers)
diff --git a/synapse/http/server.py b/synapse/http/server.py
index d4f9ad6e67..ffe6cfa09e 100644
--- a/synapse/http/server.py
+++ b/synapse/http/server.py
@@ -25,7 +25,7 @@ from io import BytesIO
from typing import Any, Callable, Dict, Tuple, Union
import jinja2
-from canonicaljson import encode_canonical_json, encode_pretty_printed_json, json
+from canonicaljson import encode_canonical_json, encode_pretty_printed_json
from twisted.internet import defer
from twisted.python import failure
@@ -46,6 +46,7 @@ from synapse.api.errors import (
from synapse.http.site import SynapseRequest
from synapse.logging.context import preserve_fn
from synapse.logging.opentracing import trace_servlet
+from synapse.util import json_encoder
from synapse.util.caches import intern_dict
logger = logging.getLogger(__name__)
@@ -242,10 +243,12 @@ class _AsyncResource(resource.Resource, metaclass=abc.ABCMeta):
no appropriate method exists. Can be overriden in sub classes for
different routing.
"""
+ # Treat HEAD requests as GET requests.
+ request_method = request.method.decode("ascii")
+ if request_method == "HEAD":
+ request_method = "GET"
- method_handler = getattr(
- self, "_async_render_%s" % (request.method.decode("ascii"),), None
- )
+ method_handler = getattr(self, "_async_render_%s" % (request_method,), None)
if method_handler:
raw_callback_return = method_handler(request)
@@ -362,11 +365,15 @@ class JsonResource(DirectServeJsonResource):
A tuple of the callback to use, the name of the servlet, and the
key word arguments to pass to the callback
"""
+ # Treat HEAD requests as GET requests.
request_path = request.path.decode("ascii")
+ request_method = request.method
+ if request_method == b"HEAD":
+ request_method = b"GET"
# Loop through all the registered callbacks to check if the method
# and path regex match
- for path_entry in self.path_regexs.get(request.method, []):
+ for path_entry in self.path_regexs.get(request_method, []):
m = path_entry.pattern.match(request_path)
if m:
# We found a match!
@@ -532,7 +539,7 @@ def respond_with_json(
# canonicaljson already encodes to bytes
json_bytes = encode_canonical_json(json_object)
else:
- json_bytes = json.dumps(json_object).encode("utf-8")
+ json_bytes = json_encoder.encode(json_object).encode("utf-8")
return respond_with_json_bytes(request, code, json_bytes, send_cors=send_cors)
@@ -579,7 +586,7 @@ def set_cors_headers(request: Request):
"""
request.setHeader(b"Access-Control-Allow-Origin", b"*")
request.setHeader(
- b"Access-Control-Allow-Methods", b"GET, POST, PUT, DELETE, OPTIONS"
+ b"Access-Control-Allow-Methods", b"GET, HEAD, POST, PUT, DELETE, OPTIONS"
)
request.setHeader(
b"Access-Control-Allow-Headers",
diff --git a/synapse/http/site.py b/synapse/http/site.py
index 6f3b2258cc..6e79b47828 100644
--- a/synapse/http/site.py
+++ b/synapse/http/site.py
@@ -146,10 +146,9 @@ class SynapseRequest(Request):
Returns a context manager; the correct way to use this is:
- @defer.inlineCallbacks
- def handle_request(request):
+ async def handle_request(request):
with request.processing("FooServlet"):
- yield really_handle_the_request()
+ await really_handle_the_request()
Once the context manager is closed, the completion of the request will be logged,
and the various metrics will be updated.
@@ -287,7 +286,9 @@ class SynapseRequest(Request):
# the connection dropped)
code += "!"
- self.site.access_logger.info(
+ log_level = logging.INFO if self._should_log_request() else logging.DEBUG
+ self.site.access_logger.log(
+ log_level,
"%s - %s - {%s}"
" Processed request: %.3fsec/%.3fsec (%.3fsec, %.3fsec) (%.3fsec/%.3fsec/%d)"
' %sB %s "%s %s %s" "%s" [%d dbevts]',
@@ -315,6 +316,17 @@ class SynapseRequest(Request):
except Exception as e:
logger.warning("Failed to stop metrics: %r", e)
+ def _should_log_request(self) -> bool:
+ """Whether we should log at INFO that we processed the request.
+ """
+ if self.path == b"/health":
+ return False
+
+ if self.method == b"OPTIONS":
+ return False
+
+ return True
+
class XForwardedForRequest(SynapseRequest):
def __init__(self, *args, **kw):
|
