Cleanup console for SDK tests (#3360)

CONTRIBUTING.md

@@ -71,6 +71,28 @@ behind this is that every PR that adds/removes public symbols fails in CI, forci
 If after checking them, it is considered that they are indeed necessary, the PR will be labeled with `Skip Public API check` so that this check is not
 run.
 
+Also, we try to keep our console output as clean as possible. Most of the time this means catching expected log messages in the test cases:
+
+``` python
+from logging import WARNING
+
+...
+
+    def test_case(self):
+        with self.assertLogs(level=WARNING):
+            some_function_that_will_log_a_warning_message()
+```
+
+Other options can be to disable logging propagation or disabling a logger altogether.
+
+A similar approach can be followed to catch warnings:
+
+``` python
+    def test_case(self):
+        with self.assertWarns(DeprecationWarning):
+            some_function_that_will_raise_a_deprecation_warning()
+```
+
 See
 [`tox.ini`](https://github.com/open-telemetry/opentelemetry-python/blob/main/tox.ini)
 for more detail on available tox commands.

opentelemetry-sdk/tests/logs/test_export.py

@@ -29,6 +29,7 @@
     LoggingHandler,
     LogRecord,
 )
+from opentelemetry.sdk._logs._internal.export import _logger
 from opentelemetry.sdk._logs.export import (
     BatchLogRecordProcessor,
     ConsoleLogExporter,
@@ -167,7 +168,8 @@ def test_simple_log_record_processor_shutdown(self):
         )
         exporter.clear()
         logger_provider.shutdown()
-        logger.warning("Log after shutdown")
+        with self.assertLogs(level=logging.WARNING):
+            logger.warning("Log after shutdown")
         finished_logs = exporter.get_finished_logs()
         self.assertEqual(len(finished_logs), 0)
 
@@ -239,7 +241,9 @@ def test_args_defaults(self):
     )
     def test_args_env_var_value_error(self):
         exporter = InMemoryLogExporter()
+        _logger.disabled = True
         log_record_processor = BatchLogRecordProcessor(exporter)
+        _logger.disabled = False
         self.assertEqual(log_record_processor._exporter, exporter)
         self.assertEqual(log_record_processor._max_queue_size, 2048)
         self.assertEqual(log_record_processor._schedule_delay_millis, 5000)
@@ -315,12 +319,14 @@ def test_shutdown(self):
         provider.add_log_record_processor(log_record_processor)
 
         logger = logging.getLogger("shutdown")
-        logger.propagate = False
         logger.addHandler(LoggingHandler(logger_provider=provider))
 
-        logger.warning("warning message: %s", "possible upcoming heatwave")
-        logger.error("Very high rise in temperatures across the globe")
-        logger.critical("Temperature hits high 420 C in Hyderabad")
+        with self.assertLogs(level=logging.WARNING):
+            logger.warning("warning message: %s", "possible upcoming heatwave")
+        with self.assertLogs(level=logging.WARNING):
+            logger.error("Very high rise in temperatures across the globe")
+        with self.assertLogs(level=logging.WARNING):
+            logger.critical("Temperature hits high 420 C in Hyderabad")
 
         log_record_processor.shutdown()
         self.assertTrue(exporter._stopped)

opentelemetry-sdk/tests/logs/test_handler.py

@@ -42,7 +42,8 @@ def test_handler_default_log_level(self):
         logger.debug("Debug message")
         self.assertEqual(emitter_mock.emit.call_count, 0)
         # Assert emit gets called for warning message
-        logger.warning("Warning message")
+        with self.assertLogs(level=logging.WARNING):
+            logger.warning("Warning message")
         self.assertEqual(emitter_mock.emit.call_count, 1)
 
     def test_handler_custom_log_level(self):
@@ -53,11 +54,14 @@ def test_handler_custom_log_level(self):
         logger = get_logger(
             level=logging.ERROR, logger_provider=emitter_provider_mock
         )
-        logger.warning("Warning message test custom log level")
+        with self.assertLogs(level=logging.WARNING):
+            logger.warning("Warning message test custom log level")
         # Make sure any log with level < ERROR is ignored
         self.assertEqual(emitter_mock.emit.call_count, 0)
-        logger.error("Mumbai, we have a major problem")
-        logger.critical("No Time For Caution")
+        with self.assertLogs(level=logging.ERROR):
+            logger.error("Mumbai, we have a major problem")
+        with self.assertLogs(level=logging.CRITICAL):
+            logger.critical("No Time For Caution")
         self.assertEqual(emitter_mock.emit.call_count, 2)
 
     def test_log_record_no_span_context(self):
@@ -67,7 +71,8 @@ def test_log_record_no_span_context(self):
         )
         logger = get_logger(logger_provider=emitter_provider_mock)
         # Assert emit gets called for warning message
-        logger.warning("Warning message")
+        with self.assertLogs(level=logging.WARNING):
+            logger.warning("Warning message")
         args, _ = emitter_mock.emit.call_args_list[0]
         log_record = args[0]
 
@@ -86,7 +91,8 @@ def test_log_record_user_attributes(self):
         )
         logger = get_logger(logger_provider=emitter_provider_mock)
         # Assert emit gets called for warning message
-        logger.warning("Warning message", extra={"http.status_code": 200})
+        with self.assertLogs(level=logging.WARNING):
+            logger.warning("Warning message", extra={"http.status_code": 200})
         args, _ = emitter_mock.emit.call_args_list[0]
         log_record = args[0]
 
@@ -104,7 +110,8 @@ def test_log_record_exception(self):
         try:
             raise ZeroDivisionError("division by zero")
         except ZeroDivisionError:
-            logger.exception("Zero Division Error")
+            with self.assertLogs(level=logging.ERROR):
+                logger.exception("Zero Division Error")
         args, _ = emitter_mock.emit.call_args_list[0]
         log_record = args[0]
 
@@ -137,7 +144,8 @@ def test_log_exc_info_false(self):
         try:
             raise ZeroDivisionError("division by zero")
         except ZeroDivisionError:
-            logger.error("Zero Division Error", exc_info=False)
+            with self.assertLogs(level=logging.ERROR):
+                logger.error("Zero Division Error", exc_info=False)
         args, _ = emitter_mock.emit.call_args_list[0]
         log_record = args[0]
 
@@ -160,7 +168,8 @@ def test_log_record_trace_correlation(self):
 
         tracer = trace.TracerProvider().get_tracer(__name__)
         with tracer.start_as_current_span("test") as span:
-            logger.critical("Critical message within span")
+            with self.assertLogs(level=logging.CRITICAL):
+                logger.critical("Critical message within span")
 
             args, _ = emitter_mock.emit.call_args_list[0]
             log_record = args[0]

opentelemetry-sdk/tests/logs/test_multi_log_processor.py

@@ -68,15 +68,18 @@ def test_log_record_processor(self):
         logger.addHandler(handler)
 
         # Test no proessor added
-        logger.critical("Odisha, we have another major cyclone")
+        with self.assertLogs(level=logging.CRITICAL):
+            logger.critical("Odisha, we have another major cyclone")
 
         self.assertEqual(len(logs_list_1), 0)
         self.assertEqual(len(logs_list_2), 0)
 
         # Add one processor
         provider.add_log_record_processor(processor1)
-        logger.warning("Brace yourself")
-        logger.error("Some error message")
+        with self.assertLogs(level=logging.WARNING):
+            logger.warning("Brace yourself")
+        with self.assertLogs(level=logging.ERROR):
+            logger.error("Some error message")
 
         expected_list_1 = [
             ("Brace yourself", "WARNING"),
@@ -86,7 +89,8 @@ def test_log_record_processor(self):
 
         # Add another processor
         provider.add_log_record_processor(processor2)
-        logger.critical("Something disastrous")
+        with self.assertLogs(level=logging.CRITICAL):
+            logger.critical("Something disastrous")
         expected_list_1.append(("Something disastrous", "CRITICAL"))
 
         expected_list_2 = [("Something disastrous", "CRITICAL")]

opentelemetry-sdk/tests/metrics/test_instrument.py

@@ -12,6 +12,7 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
+from logging import WARNING
 from unittest import TestCase
 from unittest.mock import Mock
 
@@ -50,7 +51,8 @@ def test_add(self):
     def test_add_non_monotonic(self):
         mc = Mock()
         counter = _Counter("name", Mock(), mc)
-        counter.add(-1.0)
+        with self.assertLogs(level=WARNING):
+            counter.add(-1.0)
         mc.consume_measurement.assert_not_called()
 
     def test_disallow_direct_counter_creation(self):
@@ -360,7 +362,8 @@ def test_record(self):
     def test_record_non_monotonic(self):
         mc = Mock()
         hist = _Histogram("name", Mock(), mc)
-        hist.record(-1.0)
+        with self.assertLogs(level=WARNING):
+            hist.record(-1.0)
         mc.consume_measurement.assert_not_called()
 
     def test_disallow_direct_histogram_creation(self):

opentelemetry-sdk/tests/metrics/test_metric_reader_storage.py

@@ -99,7 +99,8 @@ def test_creates_view_instrument_matches(
         # instrument2 matches view2, so should create a single
         # ViewInstrumentMatch
         MockViewInstrumentMatch.call_args_list.clear()
-        storage.consume_measurement(Measurement(1, instrument2))
+        with self.assertLogs(level=WARNING):
+            storage.consume_measurement(Measurement(1, instrument2))
         self.assertEqual(len(MockViewInstrumentMatch.call_args_list), 1)
 
     @patch(
@@ -150,7 +151,8 @@ def test_forwards_calls_to_view_instrument_match(
         view_instrument_match3.consume_measurement.assert_not_called()
 
         measurement = Measurement(1, instrument2)
-        storage.consume_measurement(measurement)
+        with self.assertLogs(level=WARNING):
+            storage.consume_measurement(measurement)
         view_instrument_match3.consume_measurement.assert_called_once_with(
             measurement
         )

opentelemetry-sdk/tests/metrics/test_metrics.py

@@ -122,19 +122,21 @@ def test_get_meter_empty(self):
         should return a NoOpMeter.
         """
 
-        meter = MeterProvider().get_meter(
-            None,
-            version="version",
-            schema_url="schema_url",
-        )
+        with self.assertLogs(level=WARNING):
+            meter = MeterProvider().get_meter(
+                None,
+                version="version",
+                schema_url="schema_url",
+            )
         self.assertIsInstance(meter, NoOpMeter)
         self.assertEqual(meter._name, None)
 
-        meter = MeterProvider().get_meter(
-            "",
-            version="version",
-            schema_url="schema_url",
-        )
+        with self.assertLogs(level=WARNING):
+            meter = MeterProvider().get_meter(
+                "",
+                version="version",
+                schema_url="schema_url",
+            )
         self.assertIsInstance(meter, NoOpMeter)
         self.assertEqual(meter._name, "")
 
@@ -483,9 +485,10 @@ def test_duplicate_instrument_aggregate_data(self):
         counter_0_0 = meter_0.create_counter(
             "counter", unit="unit", description="description"
         )
-        counter_0_1 = meter_0.create_counter(
-            "counter", unit="unit", description="description"
-        )
+        with self.assertLogs(level=WARNING):
+            counter_0_1 = meter_0.create_counter(
+                "counter", unit="unit", description="description"
+            )
         counter_1_0 = meter_1.create_counter(
             "counter", unit="unit", description="description"
         )
@@ -496,7 +499,8 @@ def test_duplicate_instrument_aggregate_data(self):
         counter_0_0.add(1, {})
         counter_0_1.add(2, {})
 
-        counter_1_0.add(7, {})
+        with self.assertLogs(level=WARNING):
+            counter_1_0.add(7, {})
 
         sleep(1)
 

opentelemetry-sdk/tests/metrics/test_periodic_exporting_metric_reader.py

@@ -13,6 +13,7 @@
 # limitations under the License.
 
 import math
+from logging import WARNING
 from time import sleep, time_ns
 from typing import Optional, Sequence
 from unittest.mock import Mock
@@ -127,7 +128,8 @@ def test_defaults(self):
         pmr = PeriodicExportingMetricReader(FakeMetricsExporter())
         self.assertEqual(pmr._export_interval_millis, 60000)
         self.assertEqual(pmr._export_timeout_millis, 30000)
-        pmr.shutdown()
+        with self.assertLogs(level=WARNING):
+            pmr.shutdown()
 
     def _create_periodic_reader(
         self, metrics, exporter, collect_wait=0, interval=60000, timeout=30000
@@ -212,8 +214,9 @@ def test_shutdown_multiple_times(self):
         pmr = self._create_periodic_reader([], FakeMetricsExporter())
         with self.assertLogs(level="WARNING") as w:
             self.run_with_many_threads(pmr.shutdown)
-            self.assertTrue("Can't shutdown multiple times", w.output[0])
-        pmr.shutdown()
+        self.assertTrue("Can't shutdown multiple times", w.output[0])
+        with self.assertLogs(level="WARNING") as w:
+            pmr.shutdown()
 
     def test_exporter_temporality_preference(self):
         exporter = FakeMetricsExporter(

opentelemetry-sdk/tests/resources/test_resources.py

@@ -16,7 +16,7 @@
 
 import unittest
 import uuid
-from logging import ERROR
+from logging import ERROR, WARNING
 from os import environ
 from unittest.mock import Mock, patch
 from urllib import parse
@@ -221,16 +221,19 @@ def test_service_name_using_process_name(self):
         )
 
     def test_invalid_resource_attribute_values(self):
-        resource = Resource(
-            {
-                SERVICE_NAME: "test",
-                "non-primitive-data-type": {},
-                "invalid-byte-type-attribute": b"\xd8\xe1\xb7\xeb\xa8\xe5 \xd2\xb7\xe1",
-                "": "empty-key-value",
-                None: "null-key-value",
-                "another-non-primitive": uuid.uuid4(),
-            }
-        )
+        with self.assertLogs(level=WARNING):
+            resource = Resource(
+                {
+                    SERVICE_NAME: "test",
+                    "non-primitive-data-type": {},
+                    "invalid-byte-type-attribute": (
+                        b"\xd8\xe1\xb7\xeb\xa8\xe5 \xd2\xb7\xe1"
+                    ),
+                    "": "empty-key-value",
+                    None: "null-key-value",
+                    "another-non-primitive": uuid.uuid4(),
+                }
+            )
         self.assertEqual(
             resource.attributes,
             {
@@ -390,12 +393,13 @@ def test_resource_detector_ignore_error(self):
         resource_detector = Mock(spec=ResourceDetector)
         resource_detector.detect.side_effect = Exception()
         resource_detector.raise_on_error = False
-        self.assertEqual(
-            get_aggregated_resources([resource_detector]),
-            _DEFAULT_RESOURCE.merge(
-                Resource({SERVICE_NAME: "unknown_service"}, "")
-            ),
-        )
+        with self.assertLogs(level=WARNING):
+            self.assertEqual(
+                get_aggregated_resources([resource_detector]),
+                _DEFAULT_RESOURCE.merge(
+                    Resource({SERVICE_NAME: "unknown_service"}, "")
+                ),
+            )
 
     def test_resource_detector_raise_error(self):
         resource_detector = Mock(spec=ResourceDetector)
@@ -470,10 +474,11 @@ def test_multiple_with_whitespace(self):
     def test_invalid_key_value_pairs(self):
         detector = OTELResourceDetector()
         environ[OTEL_RESOURCE_ATTRIBUTES] = "k=v,k2=v2,invalid,,foo=bar=baz,"
-        self.assertEqual(
-            detector.detect(),
-            Resource({"k": "v", "k2": "v2", "foo": "bar=baz"}),
-        )
+        with self.assertLogs(level=WARNING):
+            self.assertEqual(
+                detector.detect(),
+                Resource({"k": "v", "k2": "v2", "foo": "bar=baz"}),
+            )
 
     def test_multiple_with_url_decode(self):
         detector = OTELResourceDetector()