def test_engine_entry_failed(self):
inner_logger = MagicMock()
# noinspection PyTypeChecker
db_logger = DbLoggerWrapper(inner_logger, ExecuteLogManager())
finish_time = datetime.now(pytz.utc)
exception = Exception('Some failed exception')
db_logger.started(finish_time)
db_logger.finished(finish_time, exception)
with DBSession() as db:
execute = db.query(Execute).first()
db.expunge(execute)
self.assertEqual(execute.finish_time, finish_time)
self.assertEqual(execute.status, 'failed')
self.assertEqual(execute.failed_message, str(exception))
inner_logger.started.assert_called_once_with(finish_time)
inner_logger.finished.assert_called_once_with(finish_time, exception)
inner_logger.info.assert_not_called()
inner_logger.failed.assert_not_called()
inner_logger.downloaded.assert_not_called()
def test_remove_old_entries(self):
inner_logger = Mock()
settings_manager_mock = Mock()
settings_manager_mock.remove_logs_interval = 10
log_manager = ExecuteLogManager()
log_manager.remove_old_entries = Mock()
# noinspection PyTypeChecker
db_logger = DbLoggerWrapper(inner_logger, log_manager,
settings_manager_mock)
finish_time_1 = datetime.now(pytz.utc)
db_logger.started(finish_time_1)
db_logger.info(u"Message 1")
db_logger.finished(finish_time_1, None)
inner_logger.started.assert_called_once_with(finish_time_1)
inner_logger.finished.assert_called_once_with(finish_time_1, None)
inner_logger.info.assert_called_once_with("Message 1")
inner_logger.downloaded.assert_not_called()
inner_logger.failed.assert_not_called()
# noinspection PyUnresolvedReferences
log_manager.remove_old_entries.assert_called_once_with(10)
def test_engine_entry_log_failed_with_exception(self):
# noinspection PyTypeChecker
db_logger = DbLoggerWrapper(ExecuteLogManager())
finish_time = datetime.now(pytz.utc)
exception_message = u'Something Not Specified'
failed_message = u'Execute Failed'
db_logger.started(finish_time)
try:
raise Exception(exception_message)
except:
db_logger.failed(failed_message, *sys.exc_info())
db_logger.finished(finish_time, None)
with DBSession() as db:
execute = db.query(Execute).first()
db.expunge(execute)
assert execute.finish_time == finish_time
assert execute.status == 'finished'
assert execute.failed_message is None
with DBSession() as db:
entries = db.query(ExecuteLog).all()
db.expunge_all()
assert len(entries) == 1
assert exception_message in entries[0].message
assert failed_message in entries[0].message
assert 'failed' == entries[0].level
def test_engine_entry_log_mixed(self):
inner_logger = MagicMock()
# noinspection PyTypeChecker
db_logger = DbLoggerWrapper(inner_logger, ExecuteLogManager())
finish_time = datetime.now(pytz.utc)
message1 = u'Inf 1'
message2 = u'Downloaded 1'
message3 = u'Failed 1'
db_logger.started(finish_time)
entry_time = datetime.now(pytz.utc)
db_logger.info(message1)
db_logger.downloaded(message2, None)
db_logger.failed(message3)
db_logger.finished(finish_time, None)
with DBSession() as db:
execute = db.query(Execute).first()
db.expunge(execute)
self.assertEqual(execute.finish_time, finish_time)
self.assertEqual(execute.status, 'finished')
self.assertIsNone(execute.failed_message)
inner_logger.started.assert_called_once_with(finish_time)
inner_logger.finished.assert_called_once_with(finish_time, None)
inner_logger.info.assert_called_once_with(message1)
inner_logger.downloaded.assert_called_once_with(message2, None)
inner_logger.failed.assert_called_once_with(message3)
with DBSession() as db:
entries = db.query(ExecuteLog).all()
db.expunge_all()
self.assertEqual(len(entries), 3)
self.assertEqual(entries[0].message, message1)
self.assertEqual(entries[1].message, message2)
self.assertEqual(entries[2].message, message3)
# 1 seconds is enought precision for call and log results
self.assertAlmostEqual(entries[0].time,
entry_time,
delta=timedelta(seconds=1))
self.assertAlmostEqual(entries[1].time,
entry_time,
delta=timedelta(seconds=1))
self.assertAlmostEqual(entries[2].time,
entry_time,
delta=timedelta(seconds=1))
self.assertEqual(entries[0].level, 'info')
self.assertEqual(entries[1].level, 'downloaded')
self.assertEqual(entries[2].level, 'failed')
self.assertEqual(entries[0].execute_id, execute.id)
self.assertEqual(entries[1].execute_id, execute.id)
self.assertEqual(entries[2].execute_id, execute.id)
def test_engine_entry_failed(self):
inner_logger = MagicMock()
# noinspection PyTypeChecker
db_logger = DbLoggerWrapper(inner_logger, ExecuteLogManager())
finish_time = datetime.now(pytz.utc)
exception = Exception('Some failed exception')
db_logger.started(finish_time)
db_logger.finished(finish_time, exception)
with DBSession() as db:
execute = db.query(Execute).first()
db.expunge(execute)
self.assertEqual(execute.finish_time, finish_time)
self.assertEqual(execute.status, 'failed')
self.assertEqual(execute.failed_message, str(exception))
inner_logger.started.assert_called_once_with(finish_time)
inner_logger.finished.assert_called_once_with(finish_time, exception)
inner_logger.info.assert_not_called()
inner_logger.failed.assert_not_called()
inner_logger.downloaded.assert_not_called()
def test_engine_entry_log_mixed(self):
inner_logger = MagicMock()
# noinspection PyTypeChecker
db_logger = DbLoggerWrapper(inner_logger, ExecuteLogManager())
finish_time = datetime.now(pytz.utc)
message1 = u'Inf 1'
message2 = u'Downloaded 1'
message3 = u'Failed 1'
db_logger.started(finish_time)
entry_time = datetime.now(pytz.utc)
db_logger.info(message1)
db_logger.downloaded(message2, None)
db_logger.failed(message3)
db_logger.finished(finish_time, None)
with DBSession() as db:
execute = db.query(Execute).first()
db.expunge(execute)
self.assertEqual(execute.finish_time, finish_time)
self.assertEqual(execute.status, 'finished')
self.assertIsNone(execute.failed_message)
inner_logger.started.assert_called_once_with(finish_time)
inner_logger.finished.assert_called_once_with(finish_time, None)
inner_logger.info.assert_called_once_with(message1)
inner_logger.downloaded.assert_called_once_with(message2, None)
inner_logger.failed.assert_called_once_with(message3)
with DBSession() as db:
entries = db.query(ExecuteLog).all()
db.expunge_all()
self.assertEqual(len(entries), 3)
self.assertEqual(entries[0].message, message1)
self.assertEqual(entries[1].message, message2)
self.assertEqual(entries[2].message, message3)
# 1 seconds is enought precision for call and log results
self.assertAlmostEqual(entries[0].time, entry_time, delta=timedelta(seconds=1))
self.assertAlmostEqual(entries[1].time, entry_time, delta=timedelta(seconds=1))
self.assertAlmostEqual(entries[2].time, entry_time, delta=timedelta(seconds=1))
self.assertEqual(entries[0].level, 'info')
self.assertEqual(entries[1].level, 'downloaded')
self.assertEqual(entries[2].level, 'failed')
self.assertEqual(entries[0].execute_id, execute.id)
self.assertEqual(entries[1].execute_id, execute.id)
self.assertEqual(entries[2].execute_id, execute.id)
def test_engine_entry_finished(self):
# noinspection PyTypeChecker
db_logger = DbLoggerWrapper(ExecuteLogManager())
finish_time = datetime.now(pytz.utc)
db_logger.started(finish_time)
db_logger.finished(finish_time, None)
with DBSession() as db:
execute = db.query(Execute).first()
db.expunge(execute)
self.assertEqual(execute.finish_time, finish_time)
self.assertEqual(execute.status, 'finished')
self.assertIsNone(execute.failed_message)
def test_engine_entry_log_downloaded(self):
# noinspection PyTypeChecker
db_logger = DbLoggerWrapper(ExecuteLogManager())
finish_time = datetime.now(pytz.utc)
message1 = u'Downloaded 1'
message2 = u'Downloaded 2'
db_logger.started(finish_time)
downloaded_time = datetime.now(pytz.utc)
db_logger.downloaded(message1, None)
db_logger.downloaded(message2, None)
db_logger.finished(finish_time, None)
with DBSession() as db:
execute = db.query(Execute).first()
db.expunge(execute)
self.assertEqual(execute.finish_time, finish_time)
self.assertEqual(execute.status, 'finished')
self.assertIsNone(execute.failed_message)
with DBSession() as db:
entries = db.query(ExecuteLog).all()
db.expunge_all()
self.assertEqual(len(entries), 2)
self.assertEqual(entries[0].message, message1)
self.assertEqual(entries[1].message, message2)
# 1 seconds is enought precision for call and log results
self.assertAlmostEqual(entries[0].time,
downloaded_time,
delta=timedelta(seconds=1))
self.assertAlmostEqual(entries[1].time,
downloaded_time,
delta=timedelta(seconds=1))
self.assertEqual(entries[0].level, 'downloaded')
self.assertEqual(entries[1].level, 'downloaded')
self.assertEqual(entries[0].execute_id, execute.id)
self.assertEqual(entries[1].execute_id, execute.id)
def test_remove_old_entries(self):
inner_logger = Mock()
settings_manager_mock = Mock()
settings_manager_mock.remove_logs_interval = 10
log_manager = ExecuteLogManager()
log_manager.remove_old_entries = Mock()
# noinspection PyTypeChecker
db_logger = DbLoggerWrapper(inner_logger, log_manager, settings_manager_mock)
finish_time_1 = datetime.now(pytz.utc)
db_logger.started(finish_time_1)
db_logger.info(u"Message 1")
db_logger.finished(finish_time_1, None)
inner_logger.started.assert_called_once_with(finish_time_1)
inner_logger.finished.assert_called_once_with(finish_time_1, None)
inner_logger.info.assert_called_once_with("Message 1")
inner_logger.downloaded.assert_not_called()
inner_logger.failed.assert_not_called()
# noinspection PyUnresolvedReferences
log_manager.remove_old_entries.assert_called_once_with(10)
def test_engine_entry_log_multiple_executes(self):
inner_logger = MagicMock()
# noinspection PyTypeChecker
db_logger = DbLoggerWrapper(inner_logger, ExecuteLogManager())
finish_time_1 = datetime.now(pytz.utc)
finish_time_2 = finish_time_1 + timedelta(seconds=10)
message1 = u'Inf 1'
message2 = u'Downloaded 1'
message3 = u'Failed 1'
message4 = u'Failed 2'
exception = Exception('Some exception message')
db_logger.started(finish_time_1)
entry_time_1 = datetime.now(pytz.utc)
db_logger.info(message1)
db_logger.downloaded(message2, None)
db_logger.failed(message3)
db_logger.finished(finish_time_1, None)
db_logger.started(finish_time_2)
entry_time_2 = datetime.now(pytz.utc)
db_logger.failed(message4)
db_logger.finished(finish_time_2, exception)
with DBSession() as db:
executes = db.query(Execute).all()
execute1 = executes[0]
execute2 = executes[1]
db.expunge_all()
self.assertEqual(execute1.finish_time, finish_time_1)
self.assertEqual(execute1.status, 'finished')
self.assertIsNone(execute1.failed_message)
self.assertEqual(execute2.finish_time, finish_time_2)
self.assertEqual(execute2.status, 'failed')
self.assertEqual(execute2.failed_message, str(exception))
inner_logger.started.assert_has_calls([call(finish_time_1), call(finish_time_2)])
inner_logger.finished.assert_has_calls([call(finish_time_1, None), call(finish_time_2, exception)])
inner_logger.info.assert_called_once_with(message1)
inner_logger.downloaded.assert_called_once_with(message2, None)
inner_logger.failed.assert_has_calls([call(message3), call(message4)])
with DBSession() as db:
entries = db.query(ExecuteLog).all()
db.expunge_all()
self.assertEqual(len(entries), 4)
self.assertEqual(entries[0].message, message1)
self.assertEqual(entries[1].message, message2)
self.assertEqual(entries[2].message, message3)
self.assertEqual(entries[3].message, message4)
# 1 seconds is enought precision for call and log results
self.assertAlmostEqual(entries[0].time, entry_time_1, delta=timedelta(seconds=1))
self.assertAlmostEqual(entries[1].time, entry_time_1, delta=timedelta(seconds=1))
self.assertAlmostEqual(entries[2].time, entry_time_1, delta=timedelta(seconds=1))
self.assertAlmostEqual(entries[3].time, entry_time_2, delta=timedelta(seconds=1))
self.assertEqual(entries[0].level, 'info')
self.assertEqual(entries[1].level, 'downloaded')
self.assertEqual(entries[2].level, 'failed')
self.assertEqual(entries[3].level, 'failed')
self.assertEqual(entries[0].execute_id, execute1.id)
self.assertEqual(entries[1].execute_id, execute1.id)
self.assertEqual(entries[2].execute_id, execute1.id)
self.assertEqual(entries[3].execute_id, execute2.id)
def test_engine_entry_log_multiple_executes(self):
# noinspection PyTypeChecker
db_logger = DbLoggerWrapper(ExecuteLogManager())
finish_time_1 = datetime.now(pytz.utc)
finish_time_2 = finish_time_1 + timedelta(seconds=10)
message1 = u'Inf 1'
message2 = u'Downloaded 1'
message3 = u'Failed 1'
message4 = u'Failed 2'
exception = Exception('Some exception message')
db_logger.started(finish_time_1)
entry_time_1 = datetime.now(pytz.utc)
db_logger.info(message1)
db_logger.downloaded(message2, None)
db_logger.failed(message3)
db_logger.finished(finish_time_1, None)
db_logger.started(finish_time_2)
entry_time_2 = datetime.now(pytz.utc)
db_logger.failed(message4)
db_logger.finished(finish_time_2, exception)
with DBSession() as db:
executes = db.query(Execute).all()
execute1 = executes[0]
execute2 = executes[1]
db.expunge_all()
self.assertEqual(execute1.finish_time, finish_time_1)
self.assertEqual(execute1.status, 'finished')
self.assertIsNone(execute1.failed_message)
self.assertEqual(execute2.finish_time, finish_time_2)
self.assertEqual(execute2.status, 'failed')
self.assertEqual(execute2.failed_message, str(exception))
with DBSession() as db:
entries = db.query(ExecuteLog).all()
db.expunge_all()
self.assertEqual(len(entries), 4)
self.assertEqual(entries[0].message, message1)
self.assertEqual(entries[1].message, message2)
self.assertEqual(entries[2].message, message3)
self.assertEqual(entries[3].message, message4)
# 1 seconds is enought precision for call and log results
self.assertAlmostEqual(entries[0].time,
entry_time_1,
delta=timedelta(seconds=1))
self.assertAlmostEqual(entries[1].time,
entry_time_1,
delta=timedelta(seconds=1))
self.assertAlmostEqual(entries[2].time,
entry_time_1,
delta=timedelta(seconds=1))
self.assertAlmostEqual(entries[3].time,
entry_time_2,
delta=timedelta(seconds=1))
self.assertEqual(entries[0].level, 'info')
self.assertEqual(entries[1].level, 'downloaded')
self.assertEqual(entries[2].level, 'failed')
self.assertEqual(entries[3].level, 'failed')
self.assertEqual(entries[0].execute_id, execute1.id)
self.assertEqual(entries[1].execute_id, execute1.id)
self.assertEqual(entries[2].execute_id, execute1.id)
self.assertEqual(entries[3].execute_id, execute2.id)