Commit Graph

59 Commits

Author SHA1 Message Date
Erik Johnston 3f96dbbda7
Log method and path when dropping request due to size limit (#10091) 2021-05-28 15:57:53 +01:00
Richard van der Hoff 3ff2251754
Improved validation for received requests (#9817)
* Simplify `start_listening` callpath

* Correctly check the size of uploaded files
2021-04-23 19:20:44 +01:00
Richard van der Hoff 59d24c5bef
pass a reactor into SynapseSite (#9874) 2021-04-23 17:06:47 +01:00
Dan Callahan 1d5f0e3529
Bump black configuration to target py36 (#9781)
Signed-off-by: Dan Callahan <danc@element.io>
2021-04-13 10:41:34 +01:00
Patrick Cloke 48d44ab142
Record more information into structured logs. (#9654)
Records additional request information into the structured logs,
e.g. the requester, IP address, etc.
2021-04-08 08:01:14 -04:00
Patrick Cloke 33a02f0f52
Fix additional type hints from Twisted upgrade. (#9518) 2021-03-03 15:47:38 -05:00
Richard van der Hoff d8e95e5452
Add support for X-Forwarded-Proto (#9472)
rewrite XForwardedForRequest to set `isSecure()` based on
`X-Forwarded-Proto`. Also implement `getClientAddress()` while we're here.
2021-02-24 18:11:33 +00:00
Eric Eastwood 0a00b7ff14
Update black, and run auto formatting over the codebase (#9381)
- Update black version to the latest
 - Run black auto formatting over the codebase
    - Run autoformatting according to [`docs/code_style.md
`](80d6dc9783/docs/code_style.md)
 - Update `code_style.md` docs around installing black to use the correct version
2021-02-16 22:32:34 +00:00
Richard van der Hoff 2ec8ca5e60
Remove SynapseRequest.get_user_agent (#9069)
SynapseRequest is in danger of becoming a bit of a dumping-ground for "useful stuff relating to Requests",
which isn't really its intention (its purpose is to override render, finished and connectionLost to set up the 
LoggingContext and write the right entries to the request log).

Putting utility functions inside SynapseRequest means that lots of our code ends up requiring a
SynapseRequest when there is nothing synapse-specific about the Request at all, and any old
twisted.web.iweb.IRequest will do. This increases code coupling and makes testing more difficult.

In short: move get_user_agent out to a utility function.
2021-01-12 12:34:16 +00:00
Patrick Cloke 1619802228
Various clean-ups to the logging context code (#8935) 2020-12-14 14:19:47 -05:00
Erik Johnston f21e24ffc2
Add ability for access tokens to belong to one user but grant access to another user. (#8616)
We do it this way round so that only the "owner" can delete the access token (i.e. `/logout/all` by the "owner" also deletes that token, but `/logout/all` by the "target user" doesn't).

A future PR will add an API for creating such a token.

When the target user and authenticated entity are different the `Processed request` log line will be logged with a: `{@admin:server as @bob:server} ...`. I'm not convinced by that format (especially since it adds spaces in there, making it harder to use `cut -d ' '` to chop off the start of log lines). Suggestions welcome.
2020-10-29 15:58:44 +00:00
Patrick Cloke 34a5696f93
Fix typos and spelling errors. (#8639) 2020-10-23 12:38:40 -04:00
Erik Johnston c850dd9a8e
Fix handling of User-Agent headers with bad utf-8. (#8632) 2020-10-23 17:12:59 +01:00
Erik Johnston 2f9fd5ab00
Don't log OPTIONS request at INFO (#8049) 2020-08-07 14:53:05 +01:00
Erik Johnston 7620912d84
Add health check endpoint (#8048) 2020-08-07 14:21:24 +01:00
Patrick Cloke c36228c403
Convert run_as_background_process inner function to async. (#8032) 2020-08-06 08:20:42 -04:00
Richard van der Hoff 1ec688bf21
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
2020-07-24 09:55:47 +01:00
Richard van der Hoff 03619324fc
Create a ListenerConfig object (#7681)
This ended up being a bit more invasive than I'd hoped for (not helped by
generic_worker duplicating some of the code from homeserver), but hopefully
it's an improvement.

The idea is that, rather than storing unstructured `dict`s in the config for
the listener configurations, we instead parse it into a structured
`ListenerConfig` object.
2020-06-16 12:44:07 +01:00
Richard van der Hoff d84bdfe599
mypy for synapse.http.site (#7553) 2020-05-22 10:12:17 +01:00
Andrew Morgan 5611644519
Workaround for failure to wrap reason in Failure (#7473) 2020-05-14 17:07:24 +01:00
Richard van der Hoff 60adcbed91
Fix "'NoneType' has no attribute start|stop" logcontext errors (#7181)
Fixes #7179.
2020-03-31 15:18:41 +01:00
Erik Johnston ed630ea17c
Reduce amount of logging at INFO level. (#6862)
A lot of the things we log at INFO are now a bit superfluous, so lets
make them DEBUG logs to reduce the amount we log by default.

Co-Authored-By: Brendan Abolivier <babolivier@matrix.org>
Co-authored-by: Brendan Abolivier <github@brendanabolivier.com>
2020-02-06 13:31:05 +00:00
Richard van der Hoff feee819973
Fix exceptions on requests for non-ascii urls (#6682)
Fixes #6402
2020-01-13 12:41:51 +00:00
Richard van der Hoff b6b57ecb4e
Kill off redundant SynapseRequestFactory (#6619)
We already get the Site via the Channel, so there's no need for a dedicated
RequestFactory: we can just use the right constructor.
2020-01-03 14:19:48 +00:00
Andrew Morgan 54fef094b3
Remove usage of deprecated logger.warn method from codebase (#6271)
Replace every instance of `logger.warn` with `logger.warning` as the former is deprecated.
2019-10-31 10:23:24 +00:00
Amber Brown 463b072b12
Move logging utilities out of the side drawer of util/ and into logging/ (#5606) 2019-07-04 00:07:04 +10:00
Amber Brown 32e7c9e7f2
Run Black. (#5482) 2019-06-20 19:32:02 +10:00
Erik Johnston 334e075dd8 Fix error when logging incomplete requests
If a connection is lost before a request is read from Request, Twisted
sets `method` (and `uri`) attributes to dummy values. These dummy values
have incorrect types (i.e. they're not bytes), and so things like
`__repr__` would raise an exception.

To fix this we had a helper method to return the method with a
consistent type.
2018-10-02 12:06:22 +01:00
Amber Brown 1f3f5fcf52
Fix client IPs being broken on Python 3 (#3908) 2018-09-20 20:14:34 +10:00
Amber Brown aeca5a5ed5
Add a regression test for logging on failed connections (#3912) 2018-09-20 16:28:18 +10:00
Richard van der Hoff ac80cb08fe Fix more b'abcd' noise in metrics 2018-09-17 17:16:50 +01:00
Richard van der Hoff f00a9d2636 Fix some b'abcd' noise in logs and metrics
Python 3 compatibility: make sure that we decode some byte sequences before we
use them to create log lines and metrics labels.
2018-09-17 16:15:42 +01:00
Amber Brown c971aa7b9d fix 2018-09-14 03:57:02 +10:00
Amber Brown 8f08d848f5 fix 2018-09-14 03:53:56 +10:00
Amber Brown 2d2828dcbc
Port http/ to Python 3 (#3771) 2018-09-06 00:10:47 +10:00
Richard van der Hoff be6527325a Fix exceptions when a connection is closed before we read the headers
This fixes bugs introduced in #3700, by making sure that we behave sanely
when an incoming connection is closed before the headers are read.
2018-08-20 18:21:10 +01:00
Amber Brown 324525f40c
Port over enough to get some sytests running on Python 3 (#3668) 2018-08-20 23:54:49 +10:00
Richard van der Hoff eaaa2248ff Refactor request logging code
This commit moves a bunch of the logic for deciding when to log the receipt and
completion of HTTP requests into SynapseRequest, rather than in the request
handling wrappers.

Advantages of this are:
 * we get logs for *all* requests (including OPTIONS and HEADs), rather than
   just those that end up hitting handlers we've remembered to decorate
   correctly.

 * when a request handler wires up a Producer (as the media stuff does
   currently, and as other things will do soon), we log at the point that all
   of the traffic has been sent to the client.
2018-08-15 13:47:52 +01:00
Amber Brown bc006b3c9d
Refactor REST API tests to use explicit reactors (#3351) 2018-07-17 20:43:18 +10:00
Krombel 4a27000548 check isort by travis 2018-07-16 13:57:33 +02:00
Richard van der Hoff 55370331da
Refactor logcontext resource usage tracking (#3501)
Factor out the resource usage tracking out to a separate object, which can be
passed around and copied independently of the logcontext itself.
2018-07-10 13:56:07 +01:00
Amber Brown 49af402019 run isort 2018-07-09 16:09:20 +10:00
Matthew Hodgson fc4f8f33be replace invalid utf8 with \ufffd 2018-07-02 11:33:02 +01:00
Matthew Hodgson 1c867f5391 a fix which doesn't NPE everywhere 2018-07-01 11:56:33 +01:00
Matthew Hodgson f131bf8d3e don't mix unicode strings with utf8-in-byte-strings
otherwise we explode with:

```
Traceback (most recent call last):
  File /usr/lib/python2.7/logging/handlers.py, line 78, in emit
    logging.FileHandler.emit(self, record)
  File /usr/lib/python2.7/logging/__init__.py, line 950, in emit
    StreamHandler.emit(self, record)
  File /usr/lib/python2.7/logging/__init__.py, line 887, in emit
    self.handleError(record)
  File /usr/lib/python2.7/logging/__init__.py, line 810, in handleError
    None, sys.stderr)
  File /usr/lib/python2.7/traceback.py, line 124, in print_exception
    _print(file, 'Traceback (most recent call last):')
  File /usr/lib/python2.7/traceback.py, line 13, in _print
    file.write(str+terminator)
  File /home/matrix/.synapse/local/lib/python2.7/site-packages/twisted/logger/_io.py, line 170, in write
    self.log.emit(self.level, format=u{log_io}, log_io=line)
  File /home/matrix/.synapse/local/lib/python2.7/site-packages/twisted/logger/_logger.py, line 144, in emit
    self.observer(event)
  File /home/matrix/.synapse/local/lib/python2.7/site-packages/twisted/logger/_observer.py, line 136, in __call__
    errorLogger = self._errorLoggerForObserver(brokenObserver)
  File /home/matrix/.synapse/local/lib/python2.7/site-packages/twisted/logger/_observer.py, line 156, in _errorLoggerForObserver
    if obs is not observer
  File /home/matrix/.synapse/local/lib/python2.7/site-packages/twisted/logger/_observer.py, line 81, in __init__
    self.log = Logger(observer=self)
  File /home/matrix/.synapse/local/lib/python2.7/site-packages/twisted/logger/_logger.py, line 64, in __init__
    namespace = self._namespaceFromCallingContext()
  File /home/matrix/.synapse/local/lib/python2.7/site-packages/twisted/logger/_logger.py, line 42, in _namespaceFromCallingContext
    return currentframe(2).f_globals[__name__]
  File /home/matrix/.synapse/local/lib/python2.7/site-packages/twisted/python/compat.py, line 93, in currentframe
    for x in range(n + 1):
RuntimeError: maximum recursion depth exceeded while calling a Python object
Logged from file site.py, line 129
  File /usr/lib/python2.7/logging/__init__.py, line 859, in emit
    msg = self.format(record)
  File /usr/lib/python2.7/logging/__init__.py, line 732, in format
    return fmt.format(record)
  File /usr/lib/python2.7/logging/__init__.py, line 471, in format
    record.message = record.getMessage()
  File /usr/lib/python2.7/logging/__init__.py, line 335, in getMessage
    msg = msg % self.args
UnicodeDecodeError: 'ascii' codec can't decode byte 0xe2 in position 4: ordinal not in range(128)
Logged from file site.py, line 129
```

...where the logger apparently recurses whilst trying to log the error, hitting the
maximum recursion depth and killing everything badly.
2018-07-01 05:08:58 +01:00
Richard van der Hoff b088aafcae Log number of events fetched from DB
When we finish processing a request, log the number of events we fetched from
the database to handle it.

[I'm trying to figure out which requests are responsible for large amounts of
event cache churn. It may turn out to be more helpful to add counts to the
prometheus per-request/block metrics, but that is an extension to this code
anyway.]
2018-06-21 06:15:03 +01:00
Michael Telatynski e6cbf47773
factor out uri redaction into a method on http 2018-06-05 18:31:40 +01:00
Amber Brown a2eb5db4a0 update metrics to be in seconds 2018-05-28 19:10:27 +10:00
Amber Brown c4fb15a06c
Merge pull request #3246 from NotAFile/py3-repr-string
use repr, not str
2018-05-24 13:00:20 -05:00
Erik Johnston dfa70adc33 Add in flight request metrics
This tracks CPU and DB usage while requests are in flight, rather than
when we write the response.
2018-05-21 16:23:06 +01:00