From 1ec688bf21cd1368a2bb86c2de977daf148eecc3 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff <1389908+richvdh@users.noreply.github.com> Date: Fri, 24 Jul 2020 09:55:47 +0100 Subject: [PATCH] Downgrade warning on client disconnect to INFO (#7928) Clients disconnecting before we finish processing the request happens from time to time. We don't need to yell about it --- changelog.d/7928.misc | 1 + synapse/http/site.py | 4 +-- tests/test_server.py | 59 +------------------------------------------ 3 files changed, 3 insertions(+), 61 deletions(-) create mode 100644 changelog.d/7928.misc diff --git a/changelog.d/7928.misc b/changelog.d/7928.misc new file mode 100644 index 0000000000..5f3aa5de0a --- /dev/null +++ b/changelog.d/7928.misc @@ -0,0 +1 @@ +When a client disconnects, don't log it as 'Error processing request'. diff --git a/synapse/http/site.py b/synapse/http/site.py index cbc37eac6e..6f3b2258cc 100644 --- a/synapse/http/site.py +++ b/synapse/http/site.py @@ -215,9 +215,7 @@ class SynapseRequest(Request): # It's useful to log it here so that we can get an idea of when # the client disconnects. with PreserveLoggingContext(self.logcontext): - logger.warning( - "Error processing request %r: %s %s", self, reason.type, reason.value - ) + logger.info("Connection from client lost before response was sent") if not self._is_processing: self._finished_processing() diff --git a/tests/test_server.py b/tests/test_server.py index 030f58cbdc..42cada8964 100644 --- a/tests/test_server.py +++ b/tests/test_server.py @@ -12,26 +12,20 @@ # See the License for the specific language governing permissions and # limitations under the License. -import logging import re -from io import StringIO from twisted.internet.defer import Deferred -from twisted.python.failure import Failure -from twisted.test.proto_helpers import AccumulatingProtocol from twisted.web.resource import Resource -from twisted.web.server import NOT_DONE_YET from synapse.api.errors import Codes, RedirectException, SynapseError from synapse.config.server import parse_listener_def from synapse.http.server import DirectServeHtmlResource, JsonResource, OptionsResource -from synapse.http.site import SynapseSite, logger +from synapse.http.site import SynapseSite from synapse.logging.context import make_deferred_yieldable from synapse.util import Clock from tests import unittest from tests.server import ( - FakeTransport, ThreadedMemoryReactorClock, make_request, render, @@ -318,54 +312,3 @@ class WrapHtmlRequestHandlerTests(unittest.TestCase): self.assertEqual(location_headers, [b"/no/over/there"]) cookies_headers = [v for k, v in headers if k == b"Set-Cookie"] self.assertEqual(cookies_headers, [b"session=yespls"]) - - -class SiteTestCase(unittest.HomeserverTestCase): - def test_lose_connection(self): - """ - We log the URI correctly redacted when we lose the connection. - """ - - class HangingResource(Resource): - """ - A Resource that strategically hangs, as if it were processing an - answer. - """ - - def render(self, request): - return NOT_DONE_YET - - # Set up a logging handler that we can inspect afterwards - output = StringIO() - handler = logging.StreamHandler(output) - logger.addHandler(handler) - old_level = logger.level - logger.setLevel(10) - self.addCleanup(logger.setLevel, old_level) - self.addCleanup(logger.removeHandler, handler) - - # Make a resource and a Site, the resource will hang and allow us to - # time out the request while it's 'processing' - base_resource = Resource() - base_resource.putChild(b"", HangingResource()) - site = SynapseSite( - "test", "site_tag", self.hs.config.listeners[0], base_resource, "1.0" - ) - - server = site.buildProtocol(None) - client = AccumulatingProtocol() - client.makeConnection(FakeTransport(server, self.reactor)) - server.makeConnection(FakeTransport(client, self.reactor)) - - # Send a request with an access token that will get redacted - server.dataReceived(b"GET /?access_token=bar HTTP/1.0\r\n\r\n") - self.pump() - - # Lose the connection - e = Failure(Exception("Failed123")) - server.connectionLost(e) - handler.flush() - - # Our access token is redacted and the failure reason is logged. - self.assertIn("/?access_token=", output.getvalue()) - self.assertIn("Failed123", output.getvalue())