Exemple #1
0
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)
Exemple #2
0
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
Exemple #3
0
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