Skip to content
This repository has been archived by the owner on Apr 26, 2024. It is now read-only.

Create a mechanism for marking tests "logcontext clean" #8399

Merged
merged 2 commits into from
Sep 28, 2020
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions changelog.d/8399.misc
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
Create a mechanism for marking tests "logcontext clean".
43 changes: 23 additions & 20 deletions synapse/logging/context.py
Original file line number Diff line number Diff line change
Expand Up @@ -65,6 +65,11 @@ def get_thread_resource_usage() -> "Optional[resource._RUsage]":
return None


# a hook which can be set during testing to assert that we aren't abusing logcontexts.
def logcontext_error(msg: str):
logger.warning(msg)


# get an id for the current thread.
#
# threading.get_ident doesn't actually return an OS-level tid, and annoyingly,
Expand Down Expand Up @@ -330,10 +335,9 @@ def __enter__(self) -> "LoggingContext":
"""Enters this logging context into thread local storage"""
old_context = set_current_context(self)
if self.previous_context != old_context:
logger.warning(
"Expected previous context %r, found %r",
self.previous_context,
old_context,
logcontext_error(
"Expected previous context %r, found %r"
% (self.previous_context, old_context,)
)
return self

Expand All @@ -346,10 +350,10 @@ def __exit__(self, type, value, traceback) -> None:
current = set_current_context(self.previous_context)
if current is not self:
if current is SENTINEL_CONTEXT:
logger.warning("Expected logging context %s was lost", self)
logcontext_error("Expected logging context %s was lost" % (self,))
else:
logger.warning(
"Expected logging context %s but found %s", self, current
logcontext_error(
"Expected logging context %s but found %s" % (self, current)
)

# the fact that we are here suggests that the caller thinks that everything
Expand Down Expand Up @@ -387,16 +391,16 @@ def start(self, rusage: "Optional[resource._RUsage]") -> None:
support getrusuage.
"""
if get_thread_id() != self.main_thread:
logger.warning("Started logcontext %s on different thread", self)
logcontext_error("Started logcontext %s on different thread" % (self,))
return

if self.finished:
logger.warning("Re-starting finished log context %s", self)
logcontext_error("Re-starting finished log context %s" % (self,))

# If we haven't already started record the thread resource usage so
# far
if self.usage_start:
logger.warning("Re-starting already-active log context %s", self)
logcontext_error("Re-starting already-active log context %s" % (self,))
else:
self.usage_start = rusage

Expand All @@ -414,17 +418,17 @@ def stop(self, rusage: "Optional[resource._RUsage]") -> None:

try:
if get_thread_id() != self.main_thread:
logger.warning("Stopped logcontext %s on different thread", self)
logcontext_error("Stopped logcontext %s on different thread" % (self,))
return

if not rusage:
return

# Record the cpu used since we started
if not self.usage_start:
logger.warning(
"Called stop on logcontext %s without recording a start rusage",
self,
logcontext_error(
"Called stop on logcontext %s without recording a start rusage"
% (self,)
)
return

Expand Down Expand Up @@ -584,14 +588,13 @@ def __exit__(self, type, value, traceback) -> None:

if context != self._new_context:
if not context:
logger.warning(
"Expected logging context %s was lost", self._new_context
logcontext_error(
"Expected logging context %s was lost" % (self._new_context,)
)
else:
logger.warning(
"Expected logging context %s but found %s",
self._new_context,
context,
logcontext_error(
"Expected logging context %s but found %s"
% (self._new_context, context,)
)


Expand Down
3 changes: 3 additions & 0 deletions tests/crypto/test_keyring.py
Original file line number Diff line number Diff line change
Expand Up @@ -41,6 +41,7 @@

from tests import unittest
from tests.test_utils import make_awaitable
from tests.unittest import logcontext_clean


class MockPerspectiveServer:
Expand All @@ -67,6 +68,7 @@ def sign_response(self, res):
signedjson.sign.sign_json(res, self.server_name, self.key)


@logcontext_clean
class KeyringTestCase(unittest.HomeserverTestCase):
def check_context(self, val, expected):
self.assertEquals(getattr(current_context(), "request", None), expected)
Expand Down Expand Up @@ -309,6 +311,7 @@ async def get_keys2(keys_to_fetch):
mock_fetcher2.get_keys.assert_called_once()


@logcontext_clean
class ServerKeyFetcherTestCase(unittest.HomeserverTestCase):
def make_homeserver(self, reactor, clock):
self.http_client = Mock()
Expand Down
15 changes: 14 additions & 1 deletion tests/unittest.py
Original file line number Diff line number Diff line change
Expand Up @@ -23,7 +23,7 @@
import time
from typing import Optional, Tuple, Type, TypeVar, Union

from mock import Mock
from mock import Mock, patch

from canonicaljson import json

Expand Down Expand Up @@ -169,6 +169,19 @@ def INFO(target):
return target


def logcontext_clean(target):
"""A decorator which marks the TestCase or method as 'logcontext_clean'

... ie, any logcontext errors should cause a test failure
"""

def logcontext_error(msg):
raise AssertionError("logcontext error: %s" % (msg))

patcher = patch("synapse.logging.context.logcontext_error", new=logcontext_error)
return patcher(target)


class HomeserverTestCase(TestCase):
"""
A base TestCase that reduces boilerplate for HomeServer-using test cases.
Expand Down