def test_block_warnings(self, monkeypatch, fake_dd):
monkeypatch.setattr(check, "_log", FakeLogger(logging.WARNING))
# Expected events:
# +0.0 start checker
# +0.2 fail with timeout
# +0.4 log warning
# +0.5 checker stopped
# +0.6 dd completes, result ignored
# +0.7 loop stopped
def complete(result):
self.results.append(result)
self.loop.call_later(0.3, checker.stop)
self.loop.call_later(0.4, self.loop.stop)
fake_dd.configure(delay=0.6)
checker = check.DirectioChecker(self.loop,
"/path",
complete,
interval=0.2)
checker.start()
self.loop.run_forever()
assert len(check._log.messages) == 1
# Matching time value is too fragile
r = re.compile(r"Checker '/path' is blocked for .+ seconds")
msg = check._log.messages[0][1]
assert re.match(r, msg)
def test_report_blocked_workers(self):
REPORT_PERIOD = 1.0 # seconds
WAIT = 10.0 # seconds
WORKERS = 3
log = FakeLogger(level=logging.DEBUG)
self.executor = executor.Executor('test',
workers_count=10,
max_tasks=self.max_tasks,
scheduler=self.scheduler,
max_workers=self.max_workers,
log=log)
self.executor.start()
time.sleep(0.1) # Give time to start all threads
# make sure we have plenty of slow tasks
slow_tasks = [Task(wait=WAIT) for n in range(WORKERS * 2)]
for task in slow_tasks:
# and also make sure to discard workers
self.executor.dispatch(task, 1.0, discard=False)
# we want to catch at least one report
time.sleep(REPORT_PERIOD * 2)
print(log.messages) # troubleshooting aid when test fails
self.assertTrue(any(
text.startswith('Worker blocked')
for (level, text, _) in log.messages))
def __init__(self):
self.id = "vm_id"
self.log = FakeLogger()
self.cif = FakeClientIF()
self.froze = False
self.thawed = False
self.errors = {}
def test_log_missing_key(self):
stats = {}
vm = FakeVM()
log = FakeLogger()
with MonkeyPatchScope([(vmstats, '_log', log)]):
vmstats.balloon(vm, stats, {})
assert len(log.messages) == 1
assert log.messages[0][0] == logging.WARNING
assert 'balloon.current' in log.messages[0][1]
def test_log_missing_key(self):
stats = {}
vm = FakeVM()
log = FakeLogger()
with MonkeyPatchScope([(vmstats, '_log', log)]):
vmstats.balloon(vm, stats, {})
self.assertEqual(len(log.messages), 1)
self.assertEqual(log.messages[0][0], logging.WARNING)
self.assertIn('balloon.current', log.messages[0][1])
def test_default_level_log(self, level):
log = FakeLogger(level)
with utils.stopwatch("message", log=log):
time.sleep(0.01)
self.assertNotEqual(log.messages, [])
level, message, kwargs = log.messages[0]
print("Logged: %s" % message, end=" ")
self.assertEqual(level, logging.DEBUG)
self.assertTrue(message.startswith("message"),
"Unexpected message: %s" % message)
def test_failure(self):
log = FakeLogger()
@logutils.traceback(log=log, msg="message")
def fail():
raise Exception
self.assertRaises(Exception, fail)
self.assertEqual(log.messages,
[(logging.ERROR, "message", {"exc_info": True})])
def test_log_inexistent_key(self):
KEY = 'this.key.cannot.exist'
sample = {}
vm = FakeVM()
log = FakeLogger()
with MonkeyPatchScope([(vmstats, '_log', log)]):
with vmstats._skip_if_missing_stats(vm):
sample[KEY]
self.assertEqual(len(log.messages), 1)
self.assertEqual(log.messages[0][0], logging.WARNING)
self.assertIn(KEY, log.messages[0][1])
def test_log_inexistent_key(self):
KEY = 'this.key.cannot.exist'
sample = {}
vm = FakeVM()
log = FakeLogger()
with MonkeyPatchScope([(vmstats, '_log', log)]):
with vmstats._skip_if_missing_stats(vm):
sample[KEY]
assert len(log.messages) == 1
assert log.messages[0][0] == logging.WARNING
assert KEY in log.messages[0][1]
def test_log_failure(self, exc_class):
def run():
raise exc_class("Threads are evil")
log = FakeLogger()
t = concurrent.thread(run, log=log)
t.start()
t.join()
level, message, kwargs = log.messages[0]
self.assertEqual(level, logging.DEBUG)
self.assertTrue(message.startswith("START thread"),
"Unxpected message: %s" % message)
level, message, kwargs = log.messages[1]
self.assertEqual(level, logging.ERROR)
self.assertTrue(message.startswith("FINISH thread"),
"Unxpected message: %s" % message)
self.assertEqual(kwargs, {"exc_info": True})
def test_log_failure(self, exc_class):
def run():
raise exc_class("Threads are evil")
log = FakeLogger()
t = concurrent.thread(run, log=log)
t.start()
t.join()
level, message, kwargs = log.messages[0]
assert level == logging.DEBUG
assert message.startswith("START thread")
assert kwargs == {}
level, message, kwargs = log.messages[1]
assert level == logging.ERROR
assert message.startswith("FINISH thread")
assert kwargs == {"exc_info": True}
def test_log_expected_exceptions(self, exc_class):
def run():
raise exc_class("Don't panic")
log = FakeLogger()
t = concurrent.thread(run, log=log)
t.start()
t.join()
level, message, kwargs = log.messages[0]
self.assertEqual(level, logging.DEBUG)
self.assertTrue(message.startswith("START thread"),
"Unxpected message: %s" % message)
level, message, kwargs = log.messages[1]
self.assertEqual(level, logging.DEBUG)
self.assertTrue(message.startswith("FINISH thread"),
"Unxpected message: %s" % message)
self.assertIn("Don't panic", message)
self.assertEqual(kwargs, {})
def test_log_expected_exceptions(self, exc_class):
def run():
raise exc_class("Don't panic")
log = FakeLogger()
t = concurrent.thread(run, log=log)
t.start()
t.join()
level, message, kwargs = log.messages[0]
assert level == logging.DEBUG
assert message.startswith("START thread")
assert kwargs == {}
level, message, kwargs = log.messages[1]
assert level == logging.DEBUG
assert message.startswith("FINISH thread")
assert "Don't panic" in message
assert kwargs == {}
def test_log_success(self):
log = FakeLogger()
def run():
log.debug("Threads are cool")
t = concurrent.thread(run, log=log)
t.start()
t.join()
level, message, kwargs = log.messages[0]
assert level == logging.DEBUG
assert message.startswith("START thread")
assert kwargs == {}
assert log.messages[1] == (logging.DEBUG, "Threads are cool", {})
level, message, kwargs = log.messages[2]
assert level == logging.DEBUG
assert message.startswith("FINISH thread")
assert kwargs == {}
def test_log_success(self):
log = FakeLogger()
def run():
log.debug("Threads are cool")
t = concurrent.thread(run, log=log)
t.start()
t.join()
level, message, kwargs = log.messages[0]
self.assertEqual(level, logging.DEBUG)
self.assertTrue(message.startswith("START thread"),
"Unxpected message: %s" % message)
self.assertEqual(kwargs, {})
self.assertEqual(log.messages[1],
(logging.DEBUG, "Threads are cool", {}))
level, message, kwargs = log.messages[2]
self.assertEqual(level, logging.DEBUG)
self.assertTrue(message.startswith("FINISH thread"),
"Unxpected message: %s" % message)
self.assertEqual(kwargs, {})
class TestDirectioChecker(VdsmTestCase):
def setUp(self):
self.loop = asyncevent.EventLoop()
self.results = []
self.checks = 1
def tearDown(self):
self.loop.close()
def complete(self, result):
self.results.append(result)
if len(self.results) == self.checks:
self.loop.stop()
def test_path_missing(self):
self.checks = 1
checker = check.DirectioChecker(self.loop, "/no/such/path",
self.complete)
checker.start()
self.loop.run_forever()
pprint.pprint(self.results)
result = self.results[0]
self.assertRaises(exception.MiscFileReadException, result.delay)
def test_path_ok(self):
self.checks = 1
with temporaryPath(data=b"blah") as path:
checker = check.DirectioChecker(self.loop, path, self.complete)
checker.start()
self.loop.run_forever()
pprint.pprint(self.results)
result = self.results[0]
delay = result.delay()
print("delay:", delay)
self.assertEqual(type(delay), float)
@MonkeyPatch(constants, "EXT_DD", "/no/such/executable")
def test_executable_missing(self):
self.checks = 1
with temporaryPath(data=b"blah") as path:
checker = check.DirectioChecker(self.loop, path, self.complete)
checker.start()
self.loop.run_forever()
pprint.pprint(self.results)
result = self.results[0]
self.assertRaises(exception.MiscFileReadException, result.delay)
@MonkeyPatch(constants, "EXT_TASKSET", "/no/such/executable")
def test_taskset_missing(self):
self.checks = 1
with temporaryPath(data=b"blah") as path:
checker = check.DirectioChecker(self.loop, path, self.complete)
checker.start()
self.loop.run_forever()
pprint.pprint(self.results)
result = self.results[0]
self.assertRaises(exception.MiscFileReadException, result.delay)
@pytest.mark.slow
@permutations([
# interval, delay, expected
(0.20, 0.10, 0.20),
(0.10, 0.12, 0.20),
])
def test_interval(self, interval, delay, expected):
self.checks = 5
clock_res = 0.01
with fake_dd(delay):
checker = check.DirectioChecker(self.loop,
"/path",
self.complete,
interval=interval)
checker.start()
self.loop.run_forever()
pprint.pprint(self.results)
for i in range(self.checks - 1):
r1 = self.results[i]
r2 = self.results[i + 1]
actual = r2.time - r1.time
self.assertAlmostEqual(actual, expected, delta=clock_res)
@MonkeyPatch(check, "_log", FakeLogger(logging.WARNING))
def test_block_warnings(self):
self.checks = 1
with fake_dd(0.3):
checker = check.DirectioChecker(self.loop,
"/path",
self.complete,
interval=0.2)
checker.start()
self.loop.run_forever()
msg = check._log.messages[0][1]
# Matching time value is too fragile
r = re.compile(r"Checker '/path' is blocked for .+ seconds")
self.assertRegexpMatches(msg, r)
# In the idle state the checker is not running so there is nothing to
# cleanup.
def test_idle_stop_ignored(self):
checker = check.DirectioChecker(self.loop, "/path", self.complete)
checker.stop() # Will be ignored
self.assertFalse(checker.is_running())
def test_idle_repr(self):
checker = check.DirectioChecker(self.loop, "/path", self.complete)
print(checker)
self.assertIn("/path", str(checker))
self.assertIn(check.IDLE, str(checker))
self.assertNotIn("next_check=", str(checker))
# In the running state, the checker complete callback will stop the event
# loop. We need to run the loop until it is stopped.
def test_running_start_raises(self):
checker = check.DirectioChecker(self.loop, "/path", self.complete)
checker.start()
try:
self.assertRaises(RuntimeError, checker.start)
finally:
self.loop.run_forever()
def test_running_repr(self):
checker = check.DirectioChecker(self.loop, "/path", self.complete)
checker.start()
try:
print(checker)
self.assertIn("/path", str(checker))
self.assertIn(check.RUNNING, str(checker))
self.assertIn("next_check=", str(checker))
finally:
self.loop.run_forever()
# In the stopping state, the checker will not call the complete callback.
# We need to wait on the checker and stop the loop when it completes.
def test_stopping_stop_ignored(self):
checker = check.DirectioChecker(self.loop, "/path", self.complete)
checker.start()
try:
checker.stop()
checker.stop() # Will be ignored
self.assertTrue(checker.is_running())
finally:
start_thread(self.wait_for_checker, checker)
self.loop.run_forever()
def test_stopping_start_raises(self):
checker = check.DirectioChecker(self.loop, "/path", self.complete)
checker.start()
try:
checker.stop()
self.assertRaises(RuntimeError, checker.start)
finally:
start_thread(self.wait_for_checker, checker)
self.loop.run_forever()
def test_stopping_repr(self):
checker = check.DirectioChecker(self.loop, "/path", self.complete)
checker.start()
try:
checker.stop()
print(checker)
self.assertIn("/path", str(checker))
self.assertIn(check.STOPPING, str(checker))
self.assertNotIn("next_check=", str(checker))
finally:
start_thread(self.wait_for_checker, checker)
self.loop.run_forever()
def wait_for_checker(self, checker):
checker.wait(5)
self.loop.call_soon_threadsafe(self.loop.stop)
def test_default_level_no_log(self):
log = FakeLogger(logging.INFO)
with utils.stopwatch("message", log=log):
pass
self.assertEqual(log.messages, [])
def test_custom_level_log(self):
log = FakeLogger(logging.INFO)
with utils.stopwatch("message", level=logging.INFO, log=log):
pass
self.assertNotEqual(log.messages, [])
def __init__(self):
self.id = "vm_id"
self.log = FakeLogger()
self.cif = FakeClientIF()
