def setUp(self): """Set up.""" class Helper(object): """Fake object with a controllable call.""" def __init__(self): self.call_count = 1 self.calls = [] self.ri = None def call(self, func): """Call function when counter is 0, then stop running.""" self.call_count -= 1 self.calls.append(func) if self.call_count == 0: for f in self.calls: f() if self.call_count <= 0: self.ri.stop() class FakeMetrics(object): """Fake Metrics object that records calls.""" def __init__(self): """Initialize calls.""" self.calls = [] def meter(self, name, count): """Record call to meter().""" self.calls.append(("meter", name, count)) def gauge(self, name, val): """Record call to gauge().""" self.calls.append(("gauge", name, round(val, 3))) def log(msg, logLevel=None): self.logged.append((msg, logLevel)) self.helper = Helper() self.fake_metrics = FakeMetrics() self.ri = ReactorInspector(self.helper.call, self.fake_metrics, loop_time=.1, log=log) self.helper.ri = self.ri self.logged = []
class ReactorInspectorTestCase(TwistedTestCase): """Test the ReactorInspector class.""" def setUp(self): """Set up.""" class Helper(object): """Fake object with a controllable call.""" def __init__(self): self.call_count = 1 self.calls = [] self.ri = None def call(self, func): """Call function when counter is 0, then stop running.""" self.call_count -= 1 self.calls.append(func) if self.call_count == 0: for f in self.calls: f() if self.call_count <= 0: self.ri.stop() class FakeMetrics(object): """Fake Metrics object that records calls.""" def __init__(self): """Initialize calls.""" self.calls = [] def meter(self, name, count): """Record call to meter().""" self.calls.append(("meter", name, count)) def gauge(self, name, val): """Record call to gauge().""" self.calls.append(("gauge", name, round(val, 3))) def log(msg, logLevel=None): self.logged.append((msg, logLevel)) self.helper = Helper() self.fake_metrics = FakeMetrics() self.ri = ReactorInspector(self.helper.call, self.fake_metrics, loop_time=.1, log=log) self.helper.ri = self.ri self.logged = [] def check_log(self, *expected, **kw): logLevel = kw.get("logLevel", None) for (msg, level) in self.logged: if level == logLevel and all(m in msg for m in expected): return msg return False def run_ri(self, call_count=None, join=True): """Set the call count and then run the ReactorInspector.""" if call_count is not None: self.helper.call_count = call_count # pylint: disable=W0201 self.start_ts = time.time() self.ri.start() # Reactor will stop after call_count calls, thanks to helper if join: self.ri.join() def test_stop(self): """It stops.""" self.run_ri(1000, join=False) assert self.ri.is_alive() self.ri.stop() self.ri.join() self.assertFalse(self.ri.is_alive()) @defer.inlineCallbacks def test_dump_frames(self): """Test how frames are dumped. Rules: - own frame must not be logged - must log all other threads - main reactor thread must have special title """ # other thread, whose frame must be logged waitingd = defer.Deferred() def waiting_function(): """Function with funny name to be checked later.""" reactor.callFromThread(waitingd.callback, True) # wait have a default value; pylint: disable=E1120 event.wait() event = threading.Event() threading.Thread(target=waiting_function).start() # Make sure the thread has entered the waiting_function yield waitingd # Set reactor_thread since we're not starting the ReactorInspector # thread here. self.ri.reactor_thread = threading.currentThread().ident # dump frames in other thread, also def dumping_function(): """Function with funny name to be checked later.""" time.sleep(.1) self.ri.dump_frames() reactor.callFromThread(d.callback, True) d = defer.Deferred() threading.Thread(target=dumping_function).start() yield d event.set() # check self.assertFalse(self.check_log("dumping_function", logLevel=logging.DEBUG)) self.assertTrue(self.check_log("Dumping Python frame", "waiting_function", logLevel=logging.DEBUG)) self.assertTrue(self.check_log("Dumping Python frame", "reactor main thread", logLevel=logging.DEBUG)) def test_reactor_ok(self): """Reactor working fast.""" self.run_ri() ok_line = self.assertTrue(self.check_log("ReactorInspector: ok", logLevel=logging.DEBUG)) # Check the metrics delay = parse_delay(ok_line) expected_metric = ("gauge", "delay", delay) self.assertEqual([expected_metric], self.fake_metrics.calls) self.assertTrue(self.ri.last_responsive_ts >= self.start_ts) @defer.inlineCallbacks def test_reactor_blocked(self): """Reactor not working fast.""" dump_frames_called = defer.Deferred() self.ri.dump_frames = lambda: dump_frames_called.callback(True) self.run_ri(0) yield dump_frames_called log_line = self.check_log("ReactorInspector", "detected unresponsive", logLevel=logging.CRITICAL) self.assertTrue(log_line) delay = parse_delay(log_line) self.assertTrue(delay >= .1) # waited for entire loop time # Check the metrics expected_metric = ("gauge", "delay", delay) self.assertEqual([expected_metric], self.fake_metrics.calls) self.assertTrue(self.ri.last_responsive_ts < self.start_ts) def test_reactor_back_alive(self): """Reactor resurrects after some loops.""" self.run_ri(3) late_line = self.check_log("ReactorInspector: late", "got: 0", logLevel=logging.WARNING) self.assertTrue(late_line) delay = parse_delay(late_line) self.assertTrue(delay >= .2) # At least 2 cycles of delay # Check the metrics expected_metric = ("gauge", "delay", delay) self.assertEqual(expected_metric, self.fake_metrics.calls[-1]) self.assertTrue(self.ri.queue.empty()) # A late reactor is not considered responsive (until a successful loop) self.assertTrue(self.ri.last_responsive_ts < self.start_ts)