Do a GC after each test to fix logcontext leaks (#4227)

* Some words about garbage collections and logcontexts

* Do a GC after each test to fix logcontext leaks

This feels like an awful hack, but...

* changelog
This commit is contained in:
Richard van der Hoff 2018-11-27 03:00:33 +01:00 committed by Amber Brown
parent e8690dec2e
commit de8772a655
3 changed files with 71 additions and 3 deletions

1
changelog.d/4227.misc Normal file
View File

@ -0,0 +1 @@
Garbage-collect after each unit test to fix logcontext leaks

View File

@ -163,7 +163,7 @@ the logcontext was set, this will make things work out ok: provided
It's all too easy to forget to ``yield``: for instance if we forgot that It's all too easy to forget to ``yield``: for instance if we forgot that
``do_some_stuff`` returned a deferred, we might plough on regardless. This ``do_some_stuff`` returned a deferred, we might plough on regardless. This
leads to a mess; it will probably work itself out eventually, but not before leads to a mess; it will probably work itself out eventually, but not before
a load of stuff has been logged against the wrong content. (Normally, other a load of stuff has been logged against the wrong context. (Normally, other
things will break, more obviously, if you forget to ``yield``, so this tends things will break, more obviously, if you forget to ``yield``, so this tends
not to be a major problem in practice.) not to be a major problem in practice.)
@ -440,3 +440,59 @@ To conclude: I think this scheme would have worked equally well, with less
danger of messing it up, and probably made some more esoteric code easier to danger of messing it up, and probably made some more esoteric code easier to
write. But again — changing the conventions of the entire Synapse codebase is write. But again — changing the conventions of the entire Synapse codebase is
not a sensible option for the marginal improvement offered. not a sensible option for the marginal improvement offered.
A note on garbage-collection of Deferred chains
-----------------------------------------------
It turns out that our logcontext rules do not play nicely with Deferred
chains which get orphaned and garbage-collected.
Imagine we have some code that looks like this:
.. code:: python
listener_queue = []
def on_something_interesting():
for d in listener_queue:
d.callback("foo")
@defer.inlineCallbacks
def await_something_interesting():
new_deferred = defer.Deferred()
listener_queue.append(new_deferred)
with PreserveLoggingContext():
yield new_deferred
Obviously, the idea here is that we have a bunch of things which are waiting
for an event. (It's just an example of the problem here, but a relatively
common one.)
Now let's imagine two further things happen. First of all, whatever was
waiting for the interesting thing goes away. (Perhaps the request times out,
or something *even more* interesting happens.)
Secondly, let's suppose that we decide that the interesting thing is never
going to happen, and we reset the listener queue:
.. code:: python
def reset_listener_queue():
listener_queue.clear()
So, both ends of the deferred chain have now dropped their references, and the
deferred chain is now orphaned, and will be garbage-collected at some point.
Note that ``await_something_interesting`` is a generator function, and when
Python garbage-collects generator functions, it gives them a chance to clean
up by making the ``yield`` raise a ``GeneratorExit`` exception. In our case,
that means that the ``__exit__`` handler of ``PreserveLoggingContext`` will
carefully restore the request context, but there is now nothing waiting for
its return, so the request context is never cleared.
To reiterate, this problem only arises when *both* ends of a deferred chain
are dropped. Dropping the the reference to a deferred you're supposed to be
calling is probably bad practice, so this doesn't actually happen too much.
Unfortunately, when it does happen, it will lead to leaked logcontexts which
are incredibly hard to track down.

View File

@ -13,7 +13,7 @@
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and # See the License for the specific language governing permissions and
# limitations under the License. # limitations under the License.
import gc
import hashlib import hashlib
import hmac import hmac
import logging import logging
@ -31,7 +31,7 @@ from synapse.http.server import JsonResource
from synapse.http.site import SynapseRequest from synapse.http.site import SynapseRequest
from synapse.server import HomeServer from synapse.server import HomeServer
from synapse.types import UserID, create_requester from synapse.types import UserID, create_requester
from synapse.util.logcontext import LoggingContextFilter from synapse.util.logcontext import LoggingContext, LoggingContextFilter
from tests.server import get_clock, make_request, render, setup_test_homeserver from tests.server import get_clock, make_request, render, setup_test_homeserver
from tests.utils import default_config from tests.utils import default_config
@ -115,6 +115,17 @@ class TestCase(unittest.TestCase):
logging.getLogger().setLevel(level) logging.getLogger().setLevel(level)
return orig() return orig()
@around(self)
def tearDown(orig):
ret = orig()
# force a GC to workaround problems with deferreds leaking logcontexts when
# they are GCed (see the logcontext docs)
gc.collect()
LoggingContext.set_current_context(LoggingContext.sentinel)
return ret
def assertObjectHasAttributes(self, attrs, obj): def assertObjectHasAttributes(self, attrs, obj):
"""Asserts that the given object has each of the attributes given, and """Asserts that the given object has each of the attributes given, and
that the value of each matches according to assertEquals.""" that the value of each matches according to assertEquals."""