summary refs log tree commit diff
path: root/synapse/util/logcontext.py (follow)
Commit message (Collapse)AuthorAgeFilesLines
* Run Black. (#5482)Amber Brown2019-06-201-40/+43
|
* Improve logging for logcontext leaks. (#5288)Richard van der Hoff2019-05-291-9/+13
|
* Implement workaround for login error.Robert Jacob2019-01-301-1/+4
| | | | Signed-off-by: Robert Jacob <xperimental@solidproject.de>
* Correctly account for cpu usage by background threads (#4074)Richard van der Hoff2018-10-231-51/+69
| | | | | | | | | | Wrap calls to deferToThread() in a thing which uses a child logcontext to attribute CPU usage to the right request. While we're in the area, remove the logcontext_tracer stuff, which is never used, and afaik doesn't work. Fixes #4064
* Include eventid in log lines when processing incoming federation ↵Richard van der Hoff2018-09-271-4/+37
| | | | | | | | | | | transactions (#3959) when processing incoming transactions, it can be hard to see what's going on, because we process a bunch of stuff in parallel, and because we may end up recursively working our way through a chain of three or four events. This commit creates a way to use logcontexts to add the relevant event ids to the log lines.
* Fix exceptions when a connection is closed before we read the headersRichard van der Hoff2018-08-201-1/+3
| | | | | This fixes bugs introduced in #3700, by making sure that we behave sanely when an incoming connection is closed before the headers are read.
* Robustness fix for logcontext filterRichard van der Hoff2018-08-201-1/+7
| | | | | Make the logcontext filter not explode if it somehow ends up with a logcontext of None, since that infinite-loops the whole logging system.
* Rename async to async_helpers because `async` is a keyword on Python 3.7 (#3678)Amber Brown2018-08-101-1/+1
|
* Don't spew errors because we can't save metrics (#3563)Amber Brown2018-07-191-0/+11
|
* Attempt to include db threads in cpu usage stats (#3496)Richard van der Hoff2018-07-101-2/+21
| | | | | Let's try to include time spent in the DB threads in the per-request/block cpu usage metrics.
* Refactor logcontext resource usage tracking (#3501)Richard van der Hoff2018-07-101-33/+111
| | | | | Factor out the resource usage tracking out to a separate object, which can be passed around and copied independently of the logcontext itself.
* run isortAmber Brown2018-07-091-3/+3
|
* Indirect evt_count updates via method callRichard van der Hoff2018-06-221-0/+11
| | | | so that we can stub it for the sentinel and not have a billion failing UTs
* Log number of events fetched from DBRichard van der Hoff2018-06-211-0/+4
| | | | | | | | | | 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.]
* update to more consistently use seconds in any metrics or loggingAmber Brown2018-05-281-12/+12
|
* CommentErik Johnston2018-05-221-1/+1
|
* Fix logcontext resource usage trackingErik Johnston2018-05-221-11/+27
|
* Merge remote-tracking branch 'origin/develop' into rav/warn_on_logcontext_failRichard van der Hoff2018-05-031-25/+53
|\
| * Fix a class of logcontext leaksRichard van der Hoff2018-05-021-22/+38
| | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | So, it turns out that if you have a first `Deferred` `D1`, you can add a callback which returns another `Deferred` `D2`, and `D2` must then complete before any further callbacks on `D1` will execute (and later callbacks on `D1` get the *result* of `D2` rather than `D2` itself). So, `D1` might have `called=True` (as in, it has started running its callbacks), but any new callbacks added to `D1` won't get run until `D2` completes - so if you `yield D1` in an `inlineCallbacks` function, your `yield` will 'block'. In conclusion: some of our assumptions in `logcontext` were invalid. We need to make sure that we don't optimise out the logcontext juggling when this situation happens. Fortunately, it is easy to detect by checking `D1.paused`.
| * Merge pull request #3144 from ↵Richard van der Hoff2018-04-301-1/+7
| |\ | | | | | | | | | | | | matrix-org/rav/run_in_background_exception_handling Trap exceptions thrown within run_in_background
| | * Trap exceptions thrown within run_in_backgroundRichard van der Hoff2018-04-271-1/+7
| | | | | | | | | | | | | | | Turn any exceptions that get thrown synchronously within run_in_background into Failures instead.
| * | Merge remote-tracking branch 'origin/develop' into rav/use_run_in_backgroundRichard van der Hoff2018-04-271-1/+6
| |\ \
| | * | Improve exception handling for background processesRichard van der Hoff2018-04-271-1/+6
| | |/ | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | There were a bunch of places where we fire off a process to happen in the background, but don't have any exception handling on it - instead relying on the unhandled error being logged when the relevent deferred gets garbage-collected. This is unsatisfactory for a number of reasons: - logging on garbage collection is best-effort and may happen some time after the error, if at all - it can be hard to figure out where the error actually happened. - it is logged as a scary CRITICAL error which (a) I always forget to grep for and (b) it's not really CRITICAL if a background process we don't care about fails. So this is an attempt to add exception handling to everything we fire off into the background.
| * / Use run_in_background in preference to preserve_fnRichard van der Hoff2018-04-271-1/+1
| |/ | | | | | | | | | | While I was going through uses of preserve_fn for other PRs, I converted places which only use the wrapped function once to use run_in_background, to avoid creating the function object.
| * add __bool__ alias to __nonzero__ methodsAdrian Tschira2018-04-151-0/+1
| | | | | | | | Signed-off-by: Adrian Tschira <nota@notafile.com>
* | Make 'unexpected logging context' into warningsRichard van der Hoff2018-03-151-2/+2
|/ | | | | I think we've now fixed enough of these that the rest can be logged at warning.
* Factor run_in_background out from preserve_fnRichard van der Hoff2018-03-081-24/+29
| | | | | It annoys me that we create temporary function objects when there's really no need for it. Let's factor the gubbins out of preserve_fn and start using it.
* Rewrite make_deferred_yieldable avoiding inlineCallbacksRichard van der Hoff2018-03-011-9/+11
| | | | | ... because (a) it's actually simpler (b) it might be marginally more performant?
* Track DB scheduling delay per-requestRichard van der Hoff2018-01-161-1/+17
| | | | | | For each request, track the amount of time spent waiting for a db connection. This entails adding it to the LoggingContext and we may as well add metrics for it while we are passing.
* Track db txn time in millisecsRichard van der Hoff2018-01-161-3/+6
| | | | ... to reduce the amount of floating-point foo we do.
* Optimise LoggingContext creation and copyingRichard van der Hoff2018-01-161-7/+18
| | | | | | | | It turns out that the only thing we use the __dict__ of LoggingContext for is `request`, and given we create lots of LoggingContexts and then copy them every time we do a db transaction or log line, using the __dict__ seems a bit redundant. Let's try to optimise things by making the request attribute explicit.
* Remove __PreservingContextDeferred tooRichard van der Hoff2017-11-141-30/+0
|
* Remove preserve_context_over_{fn, deferred}Richard van der Hoff2017-11-141-31/+0
| | | | | Both of these functions ae known to leak logcontexts. Replace the remaining calls to them and kill them off.
* replace 'except:' with 'except Exception:'Richard van der Hoff2017-10-231-1/+1
| | | | what could possibly go wrong
* Fix fixme in preserve_fnRichard van der Hoff2017-04-031-5/+1
| | | | | `preserve_fn` is no longer used as a decorator anywhere, so we can safely fix a fixme therein.
* Fix the logcontext handling in the cache wrappers (#2077)Richard van der Hoff2017-03-301-0/+23
| | | | | | | The cache wrappers had a habit of leaking the logcontext into the reactor while the lookup function was running, and then not restoring it correctly when the lookup function had completed. It's all the fault of `preserve_context_over_{fn,deferred}` which are basically a bit broken.
* Merge pull request #2026 from matrix-org/rav/logcontext_docsRichard van der Hoff2017-03-201-0/+10
|\ | | | | Logcontext docs
| * Logcontext docsRichard van der Hoff2017-03-171-0/+10
| |
* | Stop preserve_fn leaking context into the reactorRichard van der Hoff2017-03-181-32/+29
|/ | | | | | | | Fix a bug in ``logcontext.preserve_fn`` which made it leak context into the reactor, and add a test for it. Also, get rid of ``logcontext.reset_context_after_deferred``, which tried to do the same thing but had its own, different, set of bugs.
* Implement reset_context_after_deferredRichard van der Hoff2017-03-151-0/+25
| | | | | to correctly reset the context when we fire off a deferred we aren't going to wait for.
* Preserve some logcontextsErik Johnston2016-08-241-4/+11
|
* Clean up TransactionQueueErik Johnston2016-08-101-1/+0
|
* Remove commentErik Johnston2016-02-101-1/+1
|
* s/parent_context/previous_context/Erik Johnston2016-02-101-9/+9
|
* Set parent context on instansiationErik Johnston2016-02-101-2/+7
|
* Don't bother copying records on parent contextErik Johnston2016-02-091-8/+0
|
* Change logcontext warns to debugErik Johnston2016-02-091-3/+3
|
* Fix up logcontextsErik Johnston2016-02-081-4/+94
|
* Allowing tagging log contextsErik Johnston2016-02-031-1/+6
|
* copyrightsMatthew Hodgson2016-01-071-1/+1
|
* Track the time spent in the database per request.Mark Haines2015-12-071-0/+9
| | | | and track the number of transactions that request started.
* Add a setter for the current log context.Mark Haines2015-12-071-16/+24
| | | | | | Move the resource tracking inside that setter so that it is easier to make sure that the resource tracking isn't double counting the resource usage.
* Add comments to explain why we are hardcoding RUSAGE_THREADMark Haines2015-12-041-0/+8
|
* Fix warningsMark Haines2015-12-041-2/+2
|
* Track the cpu used in the main thread by each logging contextMark Haines2015-12-031-6/+70
|
* Fix log context when sending requestsErik Johnston2015-06-191-19/+33
|
* Fix up leak. Add warnings.Erik Johnston2015-05-081-1/+10
|
* Add some docsErik Johnston2015-05-081-2/+14
|
* Change the way we do logging contexts so that they survive divergencesErik Johnston2015-05-081-0/+31
|
* Update copyright noticesMark Haines2015-01-061-0/+14
|
* Drop log level for incorrect logging contexts to WARN if the context is ↵Mark Haines2014-11-251-5/+8
| | | | wrong and DEBUG if the context is missing
* Use module loggers rather than the root logger. Exceptions caused by bad ↵Mark Haines2014-11-201-1/+3
| | | | clients shouldn't cause ERROR level logging. Fix sql logging to use 'repr' rather than 'str'
* Preserve logging context in a few more places, drop the logging context ↵Mark Haines2014-11-191-0/+4
| | | | after it has been stashed to reduce potential for confusion
* Pep8 and a few doc stringsMark Haines2014-10-301-14/+37
|
* Add a request-id to each log lineMark Haines2014-10-301-0/+85