Many "Request processing failed" errors in Sentry

[DMRobertson]

By far the most common error in Sentry is https://sentry.matrix.org/sentry/sydent/issues/15493

which describes some kind of timeout.

Request processing failed: "<twisted.python.failure.Failure twisted.internet.error.TimeoutError: User timeout caused connection failure.>", Traceback (most recent call last):
  File "/opt/vectoris/env/lib/python3.7/site-packages/twisted/internet/defer.py", line 859, in _runCallbacks
    current.result, *args, **kwargs
  File "/opt/vectoris/env/lib/python3.7/site-packages/twisted/internet/defer.py", line 1751, in gotResult
    current_context.run(_inlineCallbacks, r, gen, status)
  File "/opt/vectoris/env/lib/python3.7/site-packages/twisted/internet/defer.py", line 1658, in _inlineCallbacks
    cast(Failure, result).throwExceptionIntoGenerato...

[DMRobertson]

The log line Request processing failed comes from asyncjsonwrap, which means this either comes from a POST to MsisdnRequestCodeServlet or a POST to RegisterServlet. My money's on the latter, since it makes a federation request to another homeserver. And it looks like that the other path will catch all Exceptions too.

I suggest:

• within RegisterServlet's render_POST, catch a timeout around the federation call
• • if caught, log a warning (not an error, because there's no problem in our application). Then return 500 and an appropiate error dictlog
• the spec doesn't seem to mandate anything about return codes in failure cases.

[DMRobertson]

The error report in sentry is a bit mangled. I think because we're using logger.error instead of logger.exception?

sydent/sydent/http/servlets/__init__.py

Line 184 in 443a4b2

logger.error("Request processing failed: %r, %s", fail, fail.getTraceback())

In the actual logs I can see the full traceback. One example:

https://sentry.matrix.org/sentry/sydent/issues/15493/events/0bd350436c4345a1ac8ca6eda4079200/

- sydent.http.servlets - 184 - ERROR - Request processing failed: <twisted.python.failure.Failure twisted.internet.error.DNSLookupError: DNS lookup failed: no results for hostname lookup: $HOSTNAME.
Nov  3 12:21:15 corus sydent-vectoris[29785]:   File "/opt/vectoris/env/lib/python3.7/site-packages/twisted/internet/defer.py", line 859, in _runCallbacks
Nov  3 12:21:15 corus sydent-vectoris[29785]:     current.result, *args, **kwargs
Nov  3 12:21:15 corus sydent-vectoris[29785]:   File "/opt/vectoris/env/lib/python3.7/site-packages/twisted/internet/defer.py", line 1751, in gotResult
Nov  3 12:21:15 corus sydent-vectoris[29785]:     current_context.run(_inlineCallbacks, r, gen, status)
Nov  3 12:21:15 corus sydent-vectoris[29785]:   File "/opt/vectoris/env/lib/python3.7/site-packages/twisted/internet/defer.py", line 1658, in _inlineCallbacks
Nov  3 12:21:15 corus sydent-vectoris[29785]:     cast(Failure, result).throwExceptionIntoGenerator, gen
Nov  3 12:21:15 corus sydent-vectoris[29785]:   File "/opt/vectoris/env/lib/python3.7/site-packages/twisted/python/failure.py", line 500, in throwExceptionIntoGenerator
Nov  3 12:21:15 corus sydent-vectoris[29785]:     return g.throw(self.type, self.value, self.tb)
Nov  3 12:21:15 corus sydent-vectoris[29785]: --- <exception caught here> ---
Nov  3 12:21:15 corus sydent-vectoris[29785]:   File "/opt/vectoris/sydent/sydent/http/servlets/__init__.py", line 177, in render
Nov  3 12:21:15 corus sydent-vectoris[29785]:     result = await f(self, request)
Nov  3 12:21:15 corus sydent-vectoris[29785]:   File "/opt/vectoris/sydent/sydent/http/servlets/registerservlet.py", line 65, in render_POST
Nov  3 12:21:15 corus sydent-vectoris[29785]:     1024 * 5,
Nov  3 12:21:15 corus sydent-vectoris[29785]:   File "/opt/vectoris/sydent/sydent/http/httpclient.py", line 60, in get_json
Nov  3 12:21:15 corus sydent-vectoris[29785]:     uri.encode("utf8"),
Nov  3 12:21:15 corus sydent-vectoris[29785]:   File "/opt/vectoris/env/lib/python3.7/site-packages/twisted/internet/defer.py", line 1658, in _inlineCallbacks
Nov  3 12:21:15 corus sydent-vectoris[29785]:     cast(Failure, result).throwExceptionIntoGenerator, gen
Nov  3 12:21:15 corus sydent-vectoris[29785]:   File "/opt/vectoris/env/lib/python3.7/site-packages/twisted/python/failure.py", line 500, in throwExceptionIntoGenerator
Nov  3 12:21:15 corus sydent-vectoris[29785]:     return g.throw(self.type, self.value, self.tb)
Nov  3 12:21:15 corus sydent-vectoris[29785]:   File "/opt/vectoris/sydent/sydent/http/matrixfederationagent.py", line 195, in request
Nov  3 12:21:15 corus sydent-vectoris[29785]:     res = yield agent.request(method, uri, headers, bodyProducer)
Nov  3 12:21:15 corus sydent-vectoris[29785]:   File "/opt/vectoris/env/lib/python3.7/site-packages/twisted/internet/defer.py", line 859, in _runCallbacks
Nov  3 12:21:15 corus sydent-vectoris[29785]:     current.result, *args, **kwargs
Nov  3 12:21:15 corus sydent-vectoris[29785]:   File "/opt/vectoris/env/lib/python3.7/site-packages/twisted/internet/endpoints.py", line 1023, in startConnectionAttempts
Nov  3 12:21:15 corus sydent-vectoris[29785]:     f"no results for hostname lookup: {self._hostStr}"
Nov  3 12:21:15 corus sydent-vectoris[29785]: twisted.internet.error.DNSLookupError: DNS lookup failed: no results for hostname lookup: $HOSTNAME.

[DMRobertson]

#455 Should mean that we get better exceptions now. #456 deals with some of these errors. I think that suffices to close; I can open new issues for remaining problems.