opentelemetry-sdk: stop leaking handler in loggers

While at it also fix the noopprovider test case that was working because
we were asserting against another handler.

Author: xrmx

opentelemetry-sdk/tests/logs/test_handler.py

@@ -39,7 +39,7 @@
 # pylint: disable=too-many-public-methods
 class TestLoggingHandler(unittest.TestCase):
     def test_handler_default_log_level(self):
-        processor, logger = set_up_test_logging(logging.NOTSET)
+        processor, logger, handler = set_up_test_logging(logging.NOTSET)
 
         # Make sure debug messages are ignored by default
         logger.debug("Debug message")
@@ -50,8 +50,10 @@ def test_handler_default_log_level(self):
             logger.warning("Warning message")
         self.assertEqual(processor.emit_count(), 1)
 
+        logger.removeHandler(handler)
+
     def test_handler_custom_log_level(self):
-        processor, logger = set_up_test_logging(logging.ERROR)
+        processor, logger, handler = set_up_test_logging(logging.ERROR)
 
         with self.assertLogs(level=logging.WARNING):
             logger.warning("Warning message test custom log level")
@@ -64,6 +66,8 @@ def test_handler_custom_log_level(self):
             logger.critical("No Time For Caution")
         self.assertEqual(processor.emit_count(), 2)
 
+        logger.removeHandler(handler)
+
     # pylint: disable=protected-access
     def test_log_record_emit_noop(self):
         noop_logger_provder = NoOpLoggerProvider()
@@ -78,9 +82,10 @@ def test_log_record_emit_noop(self):
         with self.assertLogs(level=logging.WARNING):
             logger.warning("Warning message")
 
+        logger.removeHandler(handler_mock)
+
     def test_log_flush_noop(self):
         no_op_logger_provider = NoOpLoggerProvider()
-        no_op_logger_provider.force_flush = Mock()
 
         logger = logging.getLogger("foo")
         handler = LoggingHandler(
@@ -91,11 +96,19 @@ def test_log_flush_noop(self):
         with self.assertLogs(level=logging.WARNING):
             logger.warning("Warning message")
 
-        logger.handlers[0].flush()
-        no_op_logger_provider.force_flush.assert_not_called()
+        # the LoggingHandler flush method will call the force_flush method of LoggerProvider in
+        # a separate thread if present. NoOpLoggerProvider is not supposed to have that
+        with patch(
+            "opentelemetry.sdk._logs._internal.threading"
+        ) as threading_mock:
+            logger.handlers[0].flush()
+
+        threading_mock.Thread.assert_not_called()
+
+        logger.removeHandler(handler)
 
     def test_log_record_no_span_context(self):
-        processor, logger = set_up_test_logging(logging.WARNING)
+        processor, logger, handler = set_up_test_logging(logging.WARNING)
 
         # Assert emit gets called for warning message
         with self.assertLogs(level=logging.WARNING):
@@ -115,18 +128,22 @@ def test_log_record_no_span_context(self):
             INVALID_SPAN_CONTEXT.trace_flags,
         )
 
+        logger.removeHandler(handler)
+
     def test_log_record_observed_timestamp(self):
-        processor, logger = set_up_test_logging(logging.WARNING)
+        processor, logger, handler = set_up_test_logging(logging.WARNING)
 
         with self.assertLogs(level=logging.WARNING):
             logger.warning("Warning message")
 
         record = processor.get_log_record(0)
         self.assertIsNotNone(record.log_record.observed_timestamp)
 
+        logger.removeHandler(handler)
+
     def test_log_record_user_attributes(self):
         """Attributes can be injected into logs by adding them to the ReadWriteLogRecord"""
-        processor, logger = set_up_test_logging(logging.WARNING)
+        processor, logger, handler = set_up_test_logging(logging.WARNING)
 
         # Assert emit gets called for warning message
         with self.assertLogs(level=logging.WARNING):
@@ -155,9 +172,11 @@ def test_log_record_user_attributes(self):
             isinstance(record.log_record.attributes, BoundedAttributes)
         )
 
+        logger.removeHandler(handler)
+
     def test_log_record_exception(self):
         """Exception information will be included in attributes"""
-        processor, logger = set_up_test_logging(logging.ERROR)
+        processor, logger, handler = set_up_test_logging(logging.ERROR)
 
         try:
             raise ZeroDivisionError("division by zero")
@@ -189,9 +208,11 @@ def test_log_record_exception(self):
         self.assertTrue("division by zero" in stack_trace)
         self.assertTrue(__file__ in stack_trace)
 
+        logger.removeHandler(handler)
+
     def test_log_record_recursive_exception(self):
         """Exception information will be included in attributes even though it is recursive"""
-        processor, logger = set_up_test_logging(logging.ERROR)
+        processor, logger, handler = set_up_test_logging(logging.ERROR)
 
         try:
             raise ZeroDivisionError(
@@ -224,9 +245,11 @@ def test_log_record_recursive_exception(self):
         self.assertTrue("division by zero" in stack_trace)
         self.assertTrue(__file__ in stack_trace)
 
+        logger.removeHandler(handler)
+
     def test_log_exc_info_false(self):
         """Exception information will not be included in attributes"""
-        processor, logger = set_up_test_logging(logging.NOTSET)
+        processor, logger, handler = set_up_test_logging(logging.NOTSET)
 
         try:
             raise ZeroDivisionError("division by zero")
@@ -251,8 +274,10 @@ def test_log_exc_info_false(self):
             record.log_record.attributes,
         )
 
+        logger.removeHandler(handler)
+
     def test_log_record_exception_with_object_payload(self):
-        processor, logger = set_up_test_logging(logging.ERROR)
+        processor, logger, handler = set_up_test_logging(logging.ERROR)
 
         class CustomException(Exception):
             def __str__(self):
@@ -287,8 +312,10 @@ def __str__(self):
         self.assertTrue("CustomException" in stack_trace)
         self.assertTrue(__file__ in stack_trace)
 
+        logger.removeHandler(handler)
+
     def test_log_record_trace_correlation(self):
-        processor, logger = set_up_test_logging(logging.WARNING)
+        processor, logger, handler = set_up_test_logging(logging.WARNING)
 
         tracer = trace.TracerProvider().get_tracer(__name__)
         with tracer.start_as_current_span("test") as span:
@@ -325,8 +352,10 @@ def test_log_record_trace_correlation(self):
                     span_context.trace_flags,
                 )
 
+        logger.removeHandler(handler)
+
     def test_log_record_trace_correlation_deprecated(self):
-        processor, logger = set_up_test_logging(logging.WARNING)
+        processor, logger, handler = set_up_test_logging(logging.WARNING)
 
         tracer = trace.TracerProvider().get_tracer(__name__)
         with tracer.start_as_current_span("test") as span:
@@ -349,22 +378,28 @@ def test_log_record_trace_correlation_deprecated(self):
                 record.log_record.trace_flags, span_context.trace_flags
             )
 
+        logger.removeHandler(handler)
+
     def test_warning_without_formatter(self):
-        processor, logger = set_up_test_logging(logging.WARNING)
+        processor, logger, handler = set_up_test_logging(logging.WARNING)
         logger.warning("Test message")
 
         record = processor.get_log_record(0)
         self.assertEqual(record.log_record.body, "Test message")
 
+        logger.removeHandler(handler)
+
     def test_exception_without_formatter(self):
-        processor, logger = set_up_test_logging(logging.WARNING)
+        processor, logger, handler = set_up_test_logging(logging.WARNING)
         logger.exception("Test exception")
 
         record = processor.get_log_record(0)
         self.assertEqual(record.log_record.body, "Test exception")
 
+        logger.removeHandler(handler)
+
     def test_warning_with_formatter(self):
-        processor, logger = set_up_test_logging(
+        processor, logger, handler = set_up_test_logging(
             logging.WARNING,
             formatter=logging.Formatter(
                 "%(name)s - %(levelname)s - %(message)s"
@@ -377,8 +412,10 @@ def test_warning_with_formatter(self):
             record.log_record.body, "foo - WARNING - Test message"
         )
 
+        logger.removeHandler(handler)
+
     def test_log_body_is_always_string_with_formatter(self):
-        processor, logger = set_up_test_logging(
+        processor, logger, handler = set_up_test_logging(
             logging.WARNING,
             formatter=logging.Formatter(
                 "%(name)s - %(levelname)s - %(message)s"
@@ -389,17 +426,21 @@ def test_log_body_is_always_string_with_formatter(self):
         record = processor.get_log_record(0)
         self.assertIsInstance(record.log_record.body, str)
 
+        logger.removeHandler(handler)
+
     @patch.dict(os.environ, {"OTEL_SDK_DISABLED": "true"})
     def test_handler_root_logger_with_disabled_sdk_does_not_go_into_recursion_error(
         self,
     ):
-        processor, logger = set_up_test_logging(
+        processor, logger, handler = set_up_test_logging(
             logging.NOTSET, root_logger=True
         )
         logger.warning("hello")
 
         self.assertEqual(processor.emit_count(), 0)
 
+        logger.removeHandler(handler)
+
     @patch.dict(os.environ, {OTEL_ATTRIBUTE_COUNT_LIMIT: "3"})
     def test_otel_attribute_count_limit_respected_in_logging_handler(self):
         """Test that OTEL_ATTRIBUTE_COUNT_LIMIT is properly respected by LoggingHandler."""
@@ -439,6 +480,8 @@ def test_otel_attribute_count_limit_respected_in_logging_handler(self):
             f"Should have 10 dropped attributes, got {record.dropped_attributes}",
         )
 
+        logger.removeHandler(handler)
+
     @patch.dict(os.environ, {OTEL_ATTRIBUTE_COUNT_LIMIT: "5"})
     def test_otel_attribute_count_limit_includes_code_attributes(self):
         """Test that OTEL_ATTRIBUTE_COUNT_LIMIT applies to all attributes including code attributes."""
@@ -476,9 +519,11 @@ def test_otel_attribute_count_limit_includes_code_attributes(self):
             f"Should have 6 dropped attributes, got {record.dropped_attributes}",
         )
 
+        logger.removeHandler(handler)
+
     def test_logging_handler_without_env_var_uses_default_limit(self):
         """Test that without OTEL_ATTRIBUTE_COUNT_LIMIT, default limit (128) should apply."""
-        processor, logger = set_up_test_logging(logging.WARNING)
+        processor, logger, handler = set_up_test_logging(logging.WARNING)
 
         # Create a log record with many attributes (more than default limit of 128)
         extra_attrs = {f"attr_{i}": f"value_{i}" for i in range(150)}
@@ -505,6 +550,8 @@ def test_logging_handler_without_env_var_uses_default_limit(self):
             f"Should have 25 dropped attributes, got {record.dropped_attributes}",
         )
 
+        logger.removeHandler(handler)
+
 
 def set_up_test_logging(level, formatter=None, root_logger=False):
     logger_provider = LoggerProvider()
@@ -515,7 +562,7 @@ def set_up_test_logging(level, formatter=None, root_logger=False):
     if formatter:
         handler.setFormatter(formatter)
     logger.addHandler(handler)
-    return processor, logger
+    return processor, logger, handler
 
 
 class FakeProcessor(LogRecordProcessor):