From a76d2663b5f777651097fb1cbbf9c904d9a6cd23 Mon Sep 17 00:00:00 2001 From: nklapste Date: Sun, 15 May 2022 15:44:33 -0400 Subject: [PATCH] Adding tests for when python warnings get logged by graypy --- setup.py | 1 + tests/integration/helper.py | 18 ++- tests/integration/test_warnings_issue.py | 135 +++++++++++++++++++++++ 3 files changed, 150 insertions(+), 4 deletions(-) create mode 100644 tests/integration/test_warnings_issue.py diff --git a/setup.py b/setup.py index 925dc12b7..3259c3b78 100755 --- a/setup.py +++ b/setup.py @@ -81,6 +81,7 @@ def run_tests(self): "mock>=2.0.0,<3.0.0", "requests>=2.20.1,<3.0.0", "amqplib>=1.0.2,<2.0.0", + "timeout-decorator>=0.5.0,<1.0.0", ], extras_require={ "amqp": ["amqplib==1.0.2"], diff --git a/tests/integration/helper.py b/tests/integration/helper.py index 6bf098189..0fedb7fca 100644 --- a/tests/integration/helper.py +++ b/tests/integration/helper.py @@ -28,7 +28,15 @@ def get_unique_message(): BASE_API_URL = 'http://127.0.0.1:9000/api/search/universal/relative?query=message:"{0}"&range=300&fields=' -def get_graylog_response(message, fields=None): +def message_check_equals(message, wanted_message): + return message["message"]["message"] == wanted_message + + +def message_check_contains(message, wanted_message): + return wanted_message in message["message"]["message"] + + +def get_graylog_response(message, fields=None, message_check=message_check_equals): """Search for a given log message (with possible additional fields) within a local Graylog instance""" fields = fields if fields else [] @@ -37,7 +45,9 @@ def get_graylog_response(message, fields=None): while True: try: return _parse_api_response( - api_response=_get_api_response(message, fields), wanted_message=message + api_response=_get_api_response(message, fields), + wanted_message=message, + message_check=message_check, ) except ValueError: sleep(2) @@ -58,11 +68,11 @@ def _get_api_response(message, fields): return api_response -def _parse_api_response(api_response, wanted_message): +def _parse_api_response(api_response, wanted_message, message_check): assert api_response.status_code == 200 print(api_response.json()) for message in api_response.json()["messages"]: - if message["message"]["message"] == wanted_message: + if message_check(message, wanted_message): return message["message"] raise ValueError( "wanted_message: '{}' not within api_response: {}".format( diff --git a/tests/integration/test_warnings_issue.py b/tests/integration/test_warnings_issue.py new file mode 100644 index 000000000..1427ee57f --- /dev/null +++ b/tests/integration/test_warnings_issue.py @@ -0,0 +1,135 @@ +#!/usr/bin/env python +# -*- coding: utf-8 -*- + +"""pytests for addressing potential issues when an overflowing +message warning gets logged by graypy. + +Related issue: +- warnings.warn print whole overflowing message, I think this is a bug #134 + +URL: +- https://github.com/severb/graypy/issues/134 +""" + +import logging +import warnings +from importlib import reload + +import pytest +import timeout_decorator + +from graypy.handler import ( + SYSLOG_LEVELS, + GELFUDPHandler, + GELFWarningChunker, + GELFTruncatingChunker, + GELFChunkOverflowWarning, +) + +from tests.helper import TEST_UDP_PORT +from tests.integration import LOCAL_GRAYLOG_UP +from tests.integration.helper import ( + get_unique_message, + get_graylog_response, + message_check_contains, +) + + +def refresh_logging(): + """Refresh the logging library to avoid any issues""" + logging.shutdown() + reload(logging) + + +@pytest.mark.parametrize("gelf_chunker", [GELFWarningChunker, GELFTruncatingChunker]) +@pytest.mark.skipif(not LOCAL_GRAYLOG_UP, reason="local Graylog instance not up") +def test_graypy_warnings_can_be_graypy_logged(gelf_chunker): + """Test that python warnings can be configured to be captured and logged + by a graypy handler""" + refresh_logging() + + logging.captureWarnings(True) + + handler = GELFUDPHandler("127.0.0.1", TEST_UDP_PORT, gelf_chunker=gelf_chunker()) + handler.setLevel(logging.DEBUG) + + logger = logging.getLogger("test_graypy_warnings_can_be_graypy_logged") + logger.addHandler(handler) + + py_warnings_logger = logging.getLogger("py.warnings") + py_warnings_logger.addHandler(handler) + + unique_warning = get_unique_message() + + warnings.warn(unique_warning) + + graylog_response = get_graylog_response( + unique_warning, message_check=message_check_contains + ) + assert unique_warning in graylog_response["message"] + assert "long_message" not in graylog_response + assert "timestamp" in graylog_response + assert SYSLOG_LEVELS[logging.WARNING] == graylog_response["level"] + + +@pytest.mark.parametrize("gelf_chunker", [GELFWarningChunker, GELFTruncatingChunker]) +@pytest.mark.skipif(not LOCAL_GRAYLOG_UP, reason="local Graylog instance not up") +def test_graypy_overflowing_warnings_recurse_forever(gelf_chunker): + """Test that if we setup Python warnings to be logged with graypy + and we send a GELF chunk overflowing message we will recurse forever. + """ + refresh_logging() + + logging.captureWarnings(True) + + handler = GELFUDPHandler( + "127.0.0.1", TEST_UDP_PORT, gelf_chunker=gelf_chunker(chunk_size=2) + ) + handler.setLevel(logging.DEBUG) + + logger = logging.getLogger("test_graypy_overflowing_warnings_recurse_forever") + logger.addHandler(handler) + + py_warnings_logger = logging.getLogger("py.warnings") + py_warnings_logger.addHandler(handler) + + unique_message = get_unique_message() + + @timeout_decorator.timeout(5) + def log_error_that_should_warning_loop_forever(): + logger.error(unique_message * 6000) + + log_error_that_should_warning_loop_forever() + + +@pytest.mark.parametrize("gelf_chunker", [GELFWarningChunker, GELFTruncatingChunker]) +@pytest.mark.skipif(not LOCAL_GRAYLOG_UP, reason="local Graylog instance not up") +def test_graypy_ignored_overflowing_warnings_halt(gelf_chunker): + """Test that if we ignore :class:`.handler.GELFChunkOverflowWarning` + graypy will not recurse forever. + """ + refresh_logging() + # NOTE: if `warnings.filterwarnings("ignore", category=GELFChunkOverflowWarning)` + # is not present the overflowing message warning will be logged by grapy + # making another overflowing message that will be logged by graypy + # making another... + warnings.filterwarnings("ignore", category=GELFChunkOverflowWarning) + + logging.captureWarnings(True) + + handler = GELFUDPHandler( + "127.0.0.1", TEST_UDP_PORT, gelf_chunker=gelf_chunker(chunk_size=2) + ) + handler.setLevel(logging.DEBUG) + + logger = logging.getLogger("test_graypy_ignored_overflowing_warnings_halt") + logger.addHandler(handler) + + py_warnings_logger = logging.getLogger("py.warnings") + py_warnings_logger.addHandler(handler) + + unique_message = get_unique_message() + + logger.error(unique_message * 6000) + # the overflowing message warning is ignored and the overflowing logger + # error message is silently dropped