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
This commit is contained in:
Richard van der Hoff 2020-07-24 09:55:47 +01:00 committed by GitHub
parent fefe9943ef
commit 1ec688bf21
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
3 changed files with 3 additions and 61 deletions

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

@ -0,0 +1 @@
When a client disconnects, don't log it as 'Error processing request'.

View file

@ -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()

View file

@ -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=<redacted>", output.getvalue())
self.assertIn("Failed123", output.getvalue())