mirror of
https://gitlab.winehq.org/wine/wine-gecko.git
synced 2024-09-13 09:24:08 -07:00
Bug 1043314 - Enforce the invariant that we have suite_start before suite_end or test_start in mozlog, r=chmanchester
This commit is contained in:
James Graham
parent
dc5d632f2e
commit
c8beff9412
@ -85,35 +85,49 @@ log_levels = dict((k.upper(), v) for v, k in
|
||||
enumerate(["critical", "error", "warning", "info", "debug"]))
|
||||
|
||||
|
||||
class LoggerState(object):
|
||||
def __init__(self):
|
||||
self.handlers = []
|
||||
self.running_tests = set()
|
||||
self.suite_started = False
|
||||
|
||||
class StructuredLogger(object):
|
||||
_lock = Lock()
|
||||
_handlers = defaultdict(list)
|
||||
_logger_states = {}
|
||||
"""Create a structured logger with the given name
|
||||
|
||||
:param name: The name of the logger.
|
||||
:param component: A subcomponent that the logger belongs to (typically a library name)
|
||||
"""
|
||||
|
||||
def __init__(self, name, component=None):
|
||||
self._running_tests = set()
|
||||
self.name = name
|
||||
self.component = component
|
||||
|
||||
with self._lock:
|
||||
if name not in self._logger_states:
|
||||
self._logger_states[name] = LoggerState()
|
||||
|
||||
@property
|
||||
def _state(self):
|
||||
return self._logger_states[self.name]
|
||||
|
||||
def add_handler(self, handler):
|
||||
"""Add a handler to the current logger"""
|
||||
self._handlers[self.name].append(handler)
|
||||
self._state.handlers.append(handler)
|
||||
|
||||
def remove_handler(self, handler):
|
||||
"""Remove a handler from the current logger"""
|
||||
for i, candidate_handler in enumerate(self._handlers[self.name][:]):
|
||||
for i, candidate_handler in enumerate(self._state.handlers[:]):
|
||||
if candidate_handler == handler:
|
||||
del self._handlers[self.name][i]
|
||||
del self._state.handlers[i]
|
||||
break
|
||||
|
||||
@property
|
||||
def handlers(self):
|
||||
"""A list of handlers that will be called when a
|
||||
message is logged from this logger"""
|
||||
return self._handlers[self.name]
|
||||
return self._state.handlers
|
||||
|
||||
def log_raw(self, data):
|
||||
if "action" not in data:
|
||||
@ -149,13 +163,28 @@ class StructuredLogger(object):
|
||||
|
||||
:param tests: List of test identifiers that will be run in the suite.
|
||||
"""
|
||||
|
||||
data = {"tests": tests}
|
||||
if run_info is not None:
|
||||
data["run_info"] = run_info
|
||||
|
||||
if self._state.suite_started:
|
||||
self.error("Got second suite_start message before suite_end. Logged with data %s" %
|
||||
json.dumps(data))
|
||||
return
|
||||
|
||||
self._state.suite_started = True
|
||||
|
||||
self._log_data("suite_start", data)
|
||||
|
||||
def suite_end(self):
|
||||
"""Log a suite_end message"""
|
||||
if not self._state.suite_started:
|
||||
self.error("Got suite_end message before suite_start.")
|
||||
return
|
||||
|
||||
self._state.suite_started = False
|
||||
|
||||
self._log_data("suite_end")
|
||||
|
||||
def test_start(self, test):
|
||||
@ -163,10 +192,13 @@ class StructuredLogger(object):
|
||||
|
||||
:param test: Identifier of the test that will run.
|
||||
"""
|
||||
if test in self._running_tests:
|
||||
self.error("test_start for %s logged while in progress." % test)
|
||||
if not self._state.suite_started:
|
||||
self.error("Got test_start message before suite_start for test %s" % (test,))
|
||||
return
|
||||
self._running_tests.add(test)
|
||||
if test in self._state.running_tests:
|
||||
self.error("test_start for %s logged while in progress." % (test,))
|
||||
return
|
||||
self._state.running_tests.add(test)
|
||||
self._log_data("test_start", {"test": test})
|
||||
|
||||
def test_status(self, test, subtest, status, expected="PASS", message=None,
|
||||
@ -197,7 +229,7 @@ class StructuredLogger(object):
|
||||
if extra is not None:
|
||||
data["extra"] = extra
|
||||
|
||||
if test not in self._running_tests:
|
||||
if test not in self._state.running_tests:
|
||||
self.error("test_status for %s logged while not in progress. "
|
||||
"Logged with data: %s" % (test, json.dumps(data)))
|
||||
return
|
||||
@ -233,11 +265,11 @@ class StructuredLogger(object):
|
||||
if extra is not None:
|
||||
data["extra"] = extra
|
||||
|
||||
if test not in self._running_tests:
|
||||
if test not in self._state.running_tests:
|
||||
self.error("test_end for %s logged while not in progress. "
|
||||
"Logged with data: %s" % (test, json.dumps(data)))
|
||||
else:
|
||||
self._running_tests.remove(test)
|
||||
self._state.running_tests.remove(test)
|
||||
self._log_data("test_end", data)
|
||||
|
||||
def process_output(self, process, data, command=None):
|
||||
|
||||
@ -32,13 +32,12 @@ class BaseStructuredTest(unittest.TestCase):
|
||||
self.handler = TestHandler()
|
||||
self.logger.add_handler(self.handler)
|
||||
|
||||
@property
|
||||
def last_item(self):
|
||||
def pop_last_item(self):
|
||||
return self.handler.items.pop()
|
||||
|
||||
def assert_log_equals(self, expected, actual=None):
|
||||
if actual is None:
|
||||
actual = self.last_item
|
||||
actual = self.pop_last_item()
|
||||
|
||||
all_expected = {"pid": os.getpid(),
|
||||
"thread": "MainThread",
|
||||
@ -57,12 +56,15 @@ class TestStructuredLog(BaseStructuredTest):
|
||||
self.logger.suite_start(["test"])
|
||||
self.assert_log_equals({"action": "suite_start",
|
||||
"tests":["test"]})
|
||||
self.logger.suite_end()
|
||||
|
||||
def test_suite_end(self):
|
||||
self.logger.suite_start([])
|
||||
self.logger.suite_end()
|
||||
self.assert_log_equals({"action": "suite_end"})
|
||||
|
||||
def test_start(self):
|
||||
self.logger.suite_start([])
|
||||
self.logger.test_start("test1")
|
||||
self.assert_log_equals({"action": "test_start",
|
||||
"test":"test1"})
|
||||
@ -70,15 +72,19 @@ class TestStructuredLog(BaseStructuredTest):
|
||||
self.logger.test_start(("test1", "==", "test1-ref"))
|
||||
self.assert_log_equals({"action": "test_start",
|
||||
"test":("test1", "==", "test1-ref")})
|
||||
self.logger.suite_end()
|
||||
|
||||
def test_start_inprogress(self):
|
||||
self.logger.suite_start([])
|
||||
self.logger.test_start("test1")
|
||||
self.logger.test_start("test1")
|
||||
self.assert_log_equals({"action": "log",
|
||||
"message": "test_start for test1 logged while in progress.",
|
||||
"level": "ERROR"})
|
||||
self.logger.suite_end()
|
||||
|
||||
def test_status(self):
|
||||
self.logger.suite_start([])
|
||||
self.logger.test_start("test1")
|
||||
self.logger.test_status("test1", "subtest name", "fail", expected="FAIL", message="Test message")
|
||||
self.assert_log_equals({"action": "test_status",
|
||||
@ -87,8 +93,10 @@ class TestStructuredLog(BaseStructuredTest):
|
||||
"message": "Test message",
|
||||
"test":"test1"})
|
||||
self.logger.test_end("test1", "OK")
|
||||
self.logger.suite_end()
|
||||
|
||||
def test_status_1(self):
|
||||
self.logger.suite_start([])
|
||||
self.logger.test_start("test1")
|
||||
self.logger.test_status("test1", "subtest name", "fail")
|
||||
self.assert_log_equals({"action": "test_status",
|
||||
@ -97,11 +105,13 @@ class TestStructuredLog(BaseStructuredTest):
|
||||
"expected": "PASS",
|
||||
"test":"test1"})
|
||||
self.logger.test_end("test1", "OK")
|
||||
self.logger.suite_end()
|
||||
|
||||
def test_status_2(self):
|
||||
self.assertRaises(ValueError, self.logger.test_status, "test1", "subtest name", "XXXUNKNOWNXXX")
|
||||
|
||||
def test_status_extra(self):
|
||||
self.logger.suite_start([])
|
||||
self.logger.test_start("test1")
|
||||
self.logger.test_status("test1", "subtest name", "FAIL", expected="PASS", extra={"data": 42})
|
||||
self.assert_log_equals({"action": "test_status",
|
||||
@ -112,8 +122,10 @@ class TestStructuredLog(BaseStructuredTest):
|
||||
"extra": {"data":42}
|
||||
})
|
||||
self.logger.test_end("test1", "OK")
|
||||
self.logger.suite_end()
|
||||
|
||||
def test_status_stack(self):
|
||||
self.logger.suite_start([])
|
||||
self.logger.test_start("test1")
|
||||
self.logger.test_status("test1", "subtest name", "FAIL", expected="PASS", stack="many\nlines\nof\nstack")
|
||||
self.assert_log_equals({"action": "test_status",
|
||||
@ -124,13 +136,15 @@ class TestStructuredLog(BaseStructuredTest):
|
||||
"stack": "many\nlines\nof\nstack"
|
||||
})
|
||||
self.logger.test_end("test1", "OK")
|
||||
self.logger.suite_end()
|
||||
|
||||
def test_status_not_started(self):
|
||||
self.logger.test_status("test_UNKNOWN", "subtest", "PASS")
|
||||
self.assertTrue(self.last_item["message"].startswith(
|
||||
self.assertTrue(self.pop_last_item()["message"].startswith(
|
||||
"test_status for test_UNKNOWN logged while not in progress. Logged with data: {"))
|
||||
|
||||
def test_end(self):
|
||||
self.logger.suite_start([])
|
||||
self.logger.test_start("test1")
|
||||
self.logger.test_end("test1", "fail", message="Test message")
|
||||
self.assert_log_equals({"action": "test_end",
|
||||
@ -138,19 +152,23 @@ class TestStructuredLog(BaseStructuredTest):
|
||||
"expected": "OK",
|
||||
"message": "Test message",
|
||||
"test":"test1"})
|
||||
self.logger.suite_end()
|
||||
|
||||
def test_end_1(self):
|
||||
self.logger.suite_start([])
|
||||
self.logger.test_start("test1")
|
||||
self.logger.test_end("test1", "PASS", expected="PASS", extra={"data":123})
|
||||
self.assert_log_equals({"action": "test_end",
|
||||
"status": "PASS",
|
||||
"extra": {"data": 123},
|
||||
"test":"test1"})
|
||||
self.logger.suite_end()
|
||||
|
||||
def test_end_2(self):
|
||||
self.assertRaises(ValueError, self.logger.test_end, "test1", "XXXUNKNOWNXXX")
|
||||
|
||||
def test_end_stack(self):
|
||||
self.logger.suite_start([])
|
||||
self.logger.test_start("test1")
|
||||
self.logger.test_end("test1", "PASS", expected="PASS", stack="many\nlines\nof\nstack")
|
||||
self.assert_log_equals({"action": "test_end",
|
||||
@ -158,22 +176,66 @@ class TestStructuredLog(BaseStructuredTest):
|
||||
"test": "test1",
|
||||
"stack": "many\nlines\nof\nstack"
|
||||
})
|
||||
self.logger.suite_end()
|
||||
|
||||
def test_end_no_start(self):
|
||||
self.logger.test_end("test1", "PASS", expected="PASS")
|
||||
self.assertTrue(self.last_item["message"].startswith(
|
||||
self.assertTrue(self.pop_last_item()["message"].startswith(
|
||||
"test_end for test1 logged while not in progress. Logged with data: {"))
|
||||
self.logger.suite_end()
|
||||
|
||||
def test_end_twice(self):
|
||||
self.logger.suite_start([])
|
||||
self.logger.test_start("test2")
|
||||
self.logger.test_end("test2", "PASS", expected="PASS")
|
||||
self.assert_log_equals({"action": "test_end",
|
||||
"status": "PASS",
|
||||
"test": "test2"})
|
||||
self.logger.test_end("test2", "PASS", expected="PASS")
|
||||
self.assertTrue(self.last_item["message"].startswith(
|
||||
last_item = self.pop_last_item()
|
||||
self.assertEquals(last_item["action"], "log")
|
||||
self.assertEquals(last_item["level"], "ERROR")
|
||||
self.assertTrue(last_item["message"].startswith(
|
||||
"test_end for test2 logged while not in progress. Logged with data: {"))
|
||||
self.logger.suite_end()
|
||||
|
||||
def test_suite_start_twice(self):
|
||||
self.logger.suite_start([])
|
||||
self.assert_log_equals({"action": "suite_start",
|
||||
"tests": []})
|
||||
self.logger.suite_start([])
|
||||
last_item = self.pop_last_item()
|
||||
self.assertEquals(last_item["action"], "log")
|
||||
self.assertEquals(last_item["level"], "ERROR")
|
||||
self.logger.suite_end()
|
||||
|
||||
def test_suite_end_no_start(self):
|
||||
self.logger.suite_start([])
|
||||
self.assert_log_equals({"action": "suite_start",
|
||||
"tests": []})
|
||||
self.logger.suite_end()
|
||||
self.assert_log_equals({"action": "suite_end"})
|
||||
self.logger.suite_end()
|
||||
last_item = self.pop_last_item()
|
||||
self.assertEquals(last_item["action"], "log")
|
||||
self.assertEquals(last_item["level"], "ERROR")
|
||||
|
||||
def test_multiple_loggers_suite_start(self):
|
||||
logger1 = structuredlog.StructuredLogger("test")
|
||||
self.logger.suite_start([])
|
||||
logger1.suite_start([])
|
||||
last_item = self.pop_last_item()
|
||||
self.assertEquals(last_item["action"], "log")
|
||||
self.assertEquals(last_item["level"], "ERROR")
|
||||
|
||||
def test_multiple_loggers_test_start(self):
|
||||
logger1 = structuredlog.StructuredLogger("test")
|
||||
self.logger.suite_start([])
|
||||
self.logger.test_start("test")
|
||||
logger1.test_start("test")
|
||||
last_item = self.pop_last_item()
|
||||
self.assertEquals(last_item["action"], "log")
|
||||
self.assertEquals(last_item["level"], "ERROR")
|
||||
|
||||
def test_process(self):
|
||||
self.logger.process_output(1234, "test output")
|
||||
|
||||
Loading…
Reference in New Issue
Block a user