class TestLog(unittest.TestCase):
def setUp(self):
self.log_msg = 'This is a message that can be used when the content does not matter.'
self.log_data = {
'This is': 'log data',
'that can be': 'used when content does not matter'
}
self.loggo = Loggo(do_print=True,
do_write=True,
log_if_graylog_disabled=False)
self.log = self.loggo.log
def test_protected_keys(self):
"""
Check that a protected name "name" is converted to "protected_name",
in order to stop error in logger later
"""
with patch('logging.Logger.log') as mock_log:
self.log(logging.INFO, 'fine', dict(name='bad', other='good'))
(_alert, _msg), kwargs = mock_log.call_args
self.assertEqual(kwargs['extra']['protected_name'], 'bad')
self.assertEqual(kwargs['extra']['other'], 'good')
def test_can_log(self):
with patch('logging.Logger.log') as logger:
level_num = 50
msg = 'Test message here'
result = self.log(level_num, msg, dict(extra='data'))
self.assertIsNone(result)
(alert, logged_msg), extras = logger.call_args
self.assertEqual(alert, level_num)
self.assertEqual(msg, logged_msg)
self.assertEqual(extras['extra']['extra'], 'data')
def test_write_to_file(self):
"""
Check that we can write logs to file
"""
mock = mock_open()
with patch('builtins.open', mock):
self.log(logging.INFO, 'An entry in our log')
mock.assert_called_with(loggo.logfile, 'a')
self.assertTrue(os.path.isfile(loggo.logfile))
def test_int_truncation(self):
"""
Log was failing to truncate big integers. Check that this is now fixed.
"""
with patch('logging.Logger.log') as mock_log:
msg = 'This is simply a test of the int truncation inside the log.'
large_number = 10**300001
log_data = dict(key=large_number)
self.log(logging.INFO, msg, log_data)
mock_log.assert_called_with(20, msg, extra=ANY)
logger_was_passed = mock_log.call_args[1]['extra']['key']
# 7500 here is the default self.truncation for loggo
done_by_hand = str(large_number)[:7500] + '...'
self.assertEqual(logger_was_passed, done_by_hand)
def test_string_truncation_fail(self):
"""
If something cannot be cast to string, we need to know about it
"""
with patch('logging.Logger.log') as mock_log:
no_string_rep = NoRepr()
result = self.loggo._force_string_and_truncate(no_string_rep, 7500)
self.assertEqual(result, '<<Unstringable input>>')
(alert, msg), kwargs = mock_log.call_args
self.assertEqual('Object could not be cast to string', msg)
def test_fail_to_add_entry(self):
with patch('logging.Logger.log') as mock_log:
no_string_rep = NoRepr()
sample = dict(fine=123, not_fine=no_string_rep)
result = self.loggo.sanitise(sample)
(alert, msg), kwargs = mock_log.call_args
self.assertEqual('Object could not be cast to string', msg)
self.assertEqual(result['not_fine'], '<<Unstringable input>>')
self.assertEqual(result['fine'], '123')
def test_log_fail(self):
with patch('logging.Logger.log') as mock_log:
mock_log.side_effect = Exception('Really dead.')
self.loggo.raise_logging_errors = True
with self.assertRaises(Exception):
self.loggo.log(logging.INFO, 'Anything')
def test_loggo_pause(self):
with patch('logging.Logger.log') as mock_log:
with loggo.pause():
loggo.log(logging.INFO, 'test')
mock_log.assert_not_called()
loggo.log(logging.INFO, 'test')
mock_log.assert_called()
def test_loggo_pause_error(self):
with patch('logging.Logger.log') as logger:
with loggo.pause():
with self.assertRaises(ValueError):
may_or_may_not_error_test('one', 'two')
(alert, msg), kwargs = logger.call_args
expected_msg = (
'*Errored during may_or_may_not_error_test(first=\'one\', '
'other=\'two\') with ValueError "no good"')
self.assertEqual(expected_msg, msg)
logger.assert_called_once()
logger.reset()
with self.assertRaises(ValueError):
may_or_may_not_error_test('one', 'two')
self.assertEqual(len(logger.call_args_list), 2)
def test_loggo_error_suppressed(self):
with patch('logging.Logger.log') as logger:
with loggo.pause(allow_errors=False):
with self.assertRaises(ValueError):
may_or_may_not_error_test('one', 'two')
logger.assert_not_called()
loggo.log(logging.INFO, 'test')
logger.assert_called_once()
def test_see_below(self):
"""legacy test, deletable if it causes problems later"""
with patch('logging.Logger.log') as logger:
loggo.log(50, 'test')
(alert, msg), kwargs = logger.call_args
self.assertFalse('-- see below:' in msg)
def test_compat(self):
test = 'a string'
with patch('loggo.Loggo.log') as logger:
loggo.log(logging.INFO, test, None)
args = logger.call_args
self.assertIsInstance(args[0][0], int)
self.assertEqual(args[0][1], test)
self.assertIsNone(args[0][2])
with patch('logging.Logger.log') as logger:
loggo.log(logging.INFO, test)
(alert, msg), kwargs = logger.call_args
self.assertEqual(test, msg)
def test_bad_args(self):
@loggo
def dummy(needed):
return needed
with self.assertRaises(TypeError):
dummy()
def test_debug(self):
with patch('loggo.Loggo.log') as logger:
self.loggo.debug(self.log_msg, self.log_data)
logger.assert_called_with(logging.DEBUG, self.log_msg,
self.log_data)
def test_info(self):
with patch('loggo.Loggo.log') as logger:
self.loggo.info(self.log_msg, self.log_data)
logger.assert_called_with(logging.INFO, self.log_msg,
self.log_data)
def test_warning(self):
with patch('loggo.Loggo.log') as logger:
self.loggo.warning(self.log_msg, self.log_data)
logger.assert_called_with(logging.WARNING, self.log_msg,
self.log_data)
def test_error(self):
with patch('loggo.Loggo.log') as logger:
self.loggo.error(self.log_msg, self.log_data)
logger.assert_called_with(logging.ERROR, self.log_msg,
self.log_data)
def test_critical(self):
with patch('loggo.Loggo.log') as logger:
self.loggo.critical(self.log_msg, self.log_data)
logger.assert_called_with(logging.CRITICAL, self.log_msg,
self.log_data)
def test_listen_to(self):
sub_loggo_facility = 'a sub logger'
sub_loggo = Loggo(facility=sub_loggo_facility)
self.loggo.listen_to(sub_loggo_facility)
self.loggo.log = Mock()
warn = 'The parent logger should log this message after sublogger logs it'
sub_loggo.log(logging.WARNING, warn)
self.loggo.log.assert_called_with(logging.WARNING, warn, ANY)
class TestLog:
def setup_method(self):
self.logfile = "./logs/logs.txt"
self.log_msg = "This is a message that can be used when the content does not matter."
self.log_data = {"This is": "log data", "that can be": "used when content does not matter"}
self.loggo = Loggo(do_print=True, do_write=True, logfile=self.logfile, log_if_graylog_disabled=False)
self.log = self.loggo.log
def test_protected_keys(self):
"""Test that protected log data keys are renamed.
Check that a protected name "name" is converted to
"protected_name", in order to stop error in logger later.
"""
with patch("logging.Logger.log") as mock_log:
self.log(logging.INFO, "fine", {"name": "bad", "other": "good"})
(_alert, _msg), kwargs = mock_log.call_args
assert kwargs["extra"]["protected_name"] == "bad"
assert kwargs["extra"]["other"] == "good"
def test_can_log(self):
with patch("logging.Logger.log") as logger:
level_num = 50
msg = "Test message here"
result = self.log(level_num, msg, {"extra": "data"})
assert result is None
(alert, logged_msg), extras = logger.call_args
assert alert == level_num
assert msg == logged_msg
assert extras["extra"]["extra"] == "data"
def test_write_to_file(self):
"""Check that we can write logs to file."""
expected_logfile = os.path.abspath(os.path.expanduser(self.logfile))
open_ = mock_open()
with patch("builtins.open", open_):
self.log(logging.INFO, "An entry in our log")
if sys.version_info < (3, 9):
expected_open_call = call(expected_logfile, "a", encoding=None)
else:
expected_open_call = call(expected_logfile, "a", encoding=None, errors=None)
open_.assert_has_calls([expected_open_call])
open_().write.assert_called()
def test_int_truncation(self):
"""Test that large ints in log data are truncated."""
truncation = 100
loggo = Loggo(truncation=truncation)
msg = "This is simply a test of the int truncation inside the log."
large_number = 10 ** (truncation + 1)
log_data = {"key": large_number}
with patch("logging.Logger.log") as mock_log:
loggo.log(logging.INFO, msg, log_data)
mock_log.assert_called_with(20, msg, extra=ANY)
logger_was_passed = mock_log.call_args[1]["extra"]["key"]
truncation_suffix = "..."
done_by_hand = str(large_number)[: truncation - len(truncation_suffix)] + truncation_suffix
assert logger_was_passed == done_by_hand
def test_string_truncation_fail(self):
"""If something cannot be cast to string, we need to know about it."""
with patch("logging.Logger.log") as mock_log:
no_string_rep = NoRepr()
result = self.loggo._force_string_and_truncate(no_string_rep, 7500)
assert result == "<<Unstringable input>>"
(alert, msg), kwargs = mock_log.call_args
assert "Object could not be cast to string" == msg
def test_msg_truncation(self):
"""Test log message truncation."""
default_truncation_len = 7500
truncation_suffix = "..."
with patch("logging.Logger.log") as mock_log:
self.loggo.info("a" * 50000)
mock_log.assert_called_with(
logging.INFO,
"a" * (default_truncation_len - len(truncation_suffix)) + truncation_suffix,
extra=ANY,
)
def test_trace_truncation(self):
"""Test that trace is truncated correctly."""
trace_truncation = 100
loggo = Loggo(trace_truncation=trace_truncation)
for trace_key in {"trace", "traceback"}:
msg = "This is simply a test of the int truncation inside the log."
large_number = 10 ** (trace_truncation + 1)
log_data = {trace_key: large_number}
with patch("logging.Logger.log") as mock_log:
loggo.log(logging.INFO, msg, log_data)
mock_log.assert_called_with(20, msg, extra=ANY)
logger_was_passed = mock_log.call_args[1]["extra"][trace_key]
truncation_suffix = "..."
done_by_hand = str(large_number)[: trace_truncation - len(truncation_suffix)] + truncation_suffix
assert logger_was_passed == done_by_hand
def test_fail_to_add_entry(self):
with patch("logging.Logger.log") as mock_log:
no_string_rep = NoRepr()
sample = {"fine": 123, "not_fine": no_string_rep}
result = self.loggo.sanitise(sample)
(alert, msg), kwargs = mock_log.call_args
assert "Object could not be cast to string" == msg
assert result["not_fine"] == "<<Unstringable input>>"
assert result["fine"] == "123"
def test_log_fail(self):
with patch("logging.Logger.log") as mock_log:
mock_log.side_effect = Exception("Really dead.")
with pytest.raises(Exception):
self.loggo.log(logging.INFO, "Anything")
def test_loggo_pause(self):
with patch("logging.Logger.log") as mock_log:
with loggo.pause():
loggo.log(logging.INFO, "test")
mock_log.assert_not_called()
loggo.log(logging.INFO, "test")
mock_log.assert_called()
def test_loggo_pause_error(self):
with patch("logging.Logger.log") as logger:
with loggo.pause():
with pytest.raises(ValueError):
may_or_may_not_error_test("one", "two")
(alert, msg), kwargs = logger.call_args
expected_msg = (
"*Errored during may_or_may_not_error_test(first='one', "
"other='two') with ValueError \"no good\""
)
assert expected_msg == msg
logger.assert_called_once()
logger.reset()
with pytest.raises(ValueError):
may_or_may_not_error_test("one", "two")
assert len(logger.call_args_list) == 2
def test_loggo_error_suppressed(self):
with patch("logging.Logger.log") as logger:
with loggo.pause(allow_errors=False):
with pytest.raises(ValueError):
may_or_may_not_error_test("one", "two")
logger.assert_not_called()
loggo.log(logging.INFO, "test")
logger.assert_called_once()
def test_see_below(self):
"""legacy test, deletable if it causes problems later."""
with patch("logging.Logger.log") as logger:
loggo.log(50, "test")
(alert, msg), kwargs = logger.call_args
assert "-- see below:" not in msg
def test_compat(self):
test = "a string"
with patch("loggo.Loggo.log") as logger:
loggo.log(logging.INFO, test, None)
args = logger.call_args
assert isinstance(args[0][0], int)
assert args[0][1] == test
assert args[0][2] is None
with patch("logging.Logger.log") as logger:
loggo.log(logging.INFO, test)
(alert, msg), kwargs = logger.call_args
assert test == msg
def test_bad_args(self):
@loggo
def dummy(needed):
return needed
with pytest.raises(TypeError):
dummy()
def _working_normally(self):
with patch("logging.Logger.log") as logger:
res = aaa()
assert res == "this"
assert logger.call_count == 2
(alert, logged_msg), extras = logger.call_args_list[0]
assert logged_msg.startswith("*Called")
(alert, logged_msg), extras = logger.call_args_list[-1]
assert logged_msg.startswith("*Returned")
def _not_logging(self):
with patch("logging.Logger.log") as logger:
res = aaa()
assert res == "this"
logger.assert_not_called()
def test_stop_and_start(self):
"""Check that the start and stop commands actually do something."""
loggo.start()
self._working_normally()
loggo.stop()
self._not_logging()
loggo.start()
self._working_normally()
def test_debug(self):
with patch("loggo.Loggo.log") as logger:
self.loggo.debug(self.log_msg, self.log_data)
logger.assert_called_with(logging.DEBUG, self.log_msg, self.log_data)
def test_info(self):
with patch("loggo.Loggo.log") as logger:
self.loggo.info(self.log_msg, self.log_data)
logger.assert_called_with(logging.INFO, self.log_msg, self.log_data)
def test_warning(self):
with patch("loggo.Loggo.log") as logger:
self.loggo.warning(self.log_msg, self.log_data)
logger.assert_called_with(logging.WARNING, self.log_msg, self.log_data)
def test_error(self):
with patch("loggo.Loggo.log") as logger:
self.loggo.error(self.log_msg, self.log_data)
logger.assert_called_with(logging.ERROR, self.log_msg, self.log_data)
def test_critical(self):
with patch("loggo.Loggo.log") as logger:
self.loggo.critical(self.log_msg, self.log_data)
logger.assert_called_with(logging.CRITICAL, self.log_msg, self.log_data)
def test_listen_to(self):
sub_loggo_facility = "a sub logger"
sub_loggo = Loggo(facility=sub_loggo_facility)
self.loggo.listen_to(sub_loggo_facility)
self.loggo.log = Mock() # type: ignore
warn = "The parent logger should log this message after sublogger logs it"
sub_loggo.log(logging.WARNING, warn)
self.loggo.log.assert_called_with(logging.WARNING, warn, ANY) # type: ignore
class TestLog(unittest.TestCase):
def setUp(self):
self.log_msg = "This is a message that can be used when the content does not matter."
self.log_data = {
"This is": "log data",
"that can be": "used when content does not matter"
}
self.loggo = Loggo(do_print=True,
do_write=True,
log_if_graylog_disabled=False)
self.log = self.loggo.log
def test_protected_keys(self):
"""Test that protected log data keys are renamed.
Check that a protected name "name" is converted to
"protected_name", in order to stop error in logger later.
"""
with patch("logging.Logger.log") as mock_log:
self.log(logging.INFO, "fine", dict(name="bad", other="good"))
(_alert, _msg), kwargs = mock_log.call_args
self.assertEqual(kwargs["extra"]["protected_name"], "bad")
self.assertEqual(kwargs["extra"]["other"], "good")
def test_can_log(self):
with patch("logging.Logger.log") as logger:
level_num = 50
msg = "Test message here"
result = self.log(level_num, msg, dict(extra="data"))
self.assertIsNone(result)
(alert, logged_msg), extras = logger.call_args
self.assertEqual(alert, level_num)
self.assertEqual(msg, logged_msg)
self.assertEqual(extras["extra"]["extra"], "data")
def test_write_to_file(self):
"""Check that we can write logs to file."""
mock = mock_open()
with patch("builtins.open", mock):
self.log(logging.INFO, "An entry in our log")
mock.assert_called_with(loggo.logfile, "a", encoding=None)
self.assertTrue(os.path.isfile(loggo.logfile))
def test_int_truncation(self):
"""Test that large ints in log data are truncated."""
with patch("logging.Logger.log") as mock_log:
msg = "This is simply a test of the int truncation inside the log."
large_number = 10**300001
log_data = dict(key=large_number)
self.log(logging.INFO, msg, log_data)
mock_log.assert_called_with(20, msg, extra=ANY)
logger_was_passed = mock_log.call_args[1]["extra"]["key"]
# 7500 here is the default self.truncation for loggo
done_by_hand = str(large_number)[:7500] + "..."
self.assertEqual(logger_was_passed, done_by_hand)
def test_string_truncation_fail(self):
"""If something cannot be cast to string, we need to know about it."""
with patch("logging.Logger.log") as mock_log:
no_string_rep = NoRepr()
result = self.loggo._force_string_and_truncate(no_string_rep, 7500)
self.assertEqual(result, "<<Unstringable input>>")
(alert, msg), kwargs = mock_log.call_args
self.assertEqual("Object could not be cast to string", msg)
def test_fail_to_add_entry(self):
with patch("logging.Logger.log") as mock_log:
no_string_rep = NoRepr()
sample = dict(fine=123, not_fine=no_string_rep)
result = self.loggo.sanitise(sample)
(alert, msg), kwargs = mock_log.call_args
self.assertEqual("Object could not be cast to string", msg)
self.assertEqual(result["not_fine"], "<<Unstringable input>>")
self.assertEqual(result["fine"], "123")
def test_log_fail(self):
with patch("logging.Logger.log") as mock_log:
mock_log.side_effect = Exception("Really dead.")
with self.assertRaises(Exception):
self.loggo.log(logging.INFO, "Anything")
def test_loggo_pause(self):
with patch("logging.Logger.log") as mock_log:
with loggo.pause():
loggo.log(logging.INFO, "test")
mock_log.assert_not_called()
loggo.log(logging.INFO, "test")
mock_log.assert_called()
def test_loggo_pause_error(self):
with patch("logging.Logger.log") as logger:
with loggo.pause():
with self.assertRaises(ValueError):
may_or_may_not_error_test("one", "two")
(alert, msg), kwargs = logger.call_args
expected_msg = (
"*Errored during may_or_may_not_error_test(first='one', "
"other='two') with ValueError \"no good\"")
self.assertEqual(expected_msg, msg)
logger.assert_called_once()
logger.reset()
with self.assertRaises(ValueError):
may_or_may_not_error_test("one", "two")
self.assertEqual(len(logger.call_args_list), 2)
def test_loggo_error_suppressed(self):
with patch("logging.Logger.log") as logger:
with loggo.pause(allow_errors=False):
with self.assertRaises(ValueError):
may_or_may_not_error_test("one", "two")
logger.assert_not_called()
loggo.log(logging.INFO, "test")
logger.assert_called_once()
def test_see_below(self):
"""legacy test, deletable if it causes problems later."""
with patch("logging.Logger.log") as logger:
loggo.log(50, "test")
(alert, msg), kwargs = logger.call_args
self.assertFalse("-- see below:" in msg)
def test_compat(self):
test = "a string"
with patch("loggo.Loggo.log") as logger:
loggo.log(logging.INFO, test, None)
args = logger.call_args
self.assertIsInstance(args[0][0], int)
self.assertEqual(args[0][1], test)
self.assertIsNone(args[0][2])
with patch("logging.Logger.log") as logger:
loggo.log(logging.INFO, test)
(alert, msg), kwargs = logger.call_args
self.assertEqual(test, msg)
def test_bad_args(self):
@loggo
def dummy(needed):
return needed
with self.assertRaises(TypeError):
dummy()
def _working_normally(self):
with patch("logging.Logger.log") as logger:
res = aaa()
self.assertEqual(res, "this")
self.assertEqual(logger.call_count, 2)
(alert, logged_msg), extras = logger.call_args_list[0]
self.assertTrue(logged_msg.startswith("*Called"))
(alert, logged_msg), extras = logger.call_args_list[-1]
self.assertTrue(logged_msg.startswith("*Returned"))
def _not_logging(self):
with patch("logging.Logger.log") as logger:
res = aaa()
self.assertEqual(res, "this")
logger.assert_not_called()
def test_stop_and_start(self):
"""Check that the start and stop commands actually do something."""
loggo.start()
self._working_normally()
loggo.stop()
self._not_logging()
loggo.start()
self._working_normally()
def test_debug(self):
with patch("loggo.Loggo.log") as logger:
self.loggo.debug(self.log_msg, self.log_data)
logger.assert_called_with(logging.DEBUG, self.log_msg,
self.log_data)
def test_info(self):
with patch("loggo.Loggo.log") as logger:
self.loggo.info(self.log_msg, self.log_data)
logger.assert_called_with(logging.INFO, self.log_msg,
self.log_data)
def test_warning(self):
with patch("loggo.Loggo.log") as logger:
self.loggo.warning(self.log_msg, self.log_data)
logger.assert_called_with(logging.WARNING, self.log_msg,
self.log_data)
def test_error(self):
with patch("loggo.Loggo.log") as logger:
self.loggo.error(self.log_msg, self.log_data)
logger.assert_called_with(logging.ERROR, self.log_msg,
self.log_data)
def test_critical(self):
with patch("loggo.Loggo.log") as logger:
self.loggo.critical(self.log_msg, self.log_data)
logger.assert_called_with(logging.CRITICAL, self.log_msg,
self.log_data)
def test_listen_to(self):
sub_loggo_facility = "a sub logger"
sub_loggo = Loggo(facility=sub_loggo_facility)
self.loggo.listen_to(sub_loggo_facility)
self.loggo.log = Mock() # type: ignore
warn = "The parent logger should log this message after sublogger logs it"
sub_loggo.log(logging.WARNING, warn)
self.loggo.log.assert_called_with(logging.WARNING, warn,
ANY) # type: ignore