Fix logging without a tty (#436)

This fixes logging without an iteractive session, e.g. docker without
-it or by default on k8s.

The issue there is that without explicitly adding handlers without a tty
the log are not sent to stderr.

Also we need to take care of the propagation in case the OTel Logging
handler is configured on the root logger to have also these logs
exported.

Author: xrmx

src/elasticotel/distro/config.py

@@ -31,6 +31,7 @@
     OpAMPRemoteConfigParseException,
 )
 from opentelemetry._opamp.proto import opamp_pb2 as opamp_pb2
+from opentelemetry.sdk._logs import LoggingHandler
 from opentelemetry.sdk.environment_variables import OTEL_LOG_LEVEL, OTEL_TRACES_SAMPLER_ARG
 
 
@@ -100,19 +101,24 @@ def log_env_vars(self):
             for k, v in os.environ.items()
             if k.startswith("OTEL_") or k.startswith("ELASTIC_OTEL_")
         ]
-        # we rely on the application setting up logging and we don't want to interfere with that BUT:
-        # - by default the python root logger should be at WARNING level
-        # - the EDOT Configuration dump is at INFO level
-        # - at startup we don't have application logging already setup
-        # So we add a temporary handler just for printing our config
-        handler = logging.StreamHandler()
-        logger.addHandler(handler)
+
         logger.info("EDOT Configuration")
         for k, v in sorted(env_vars):
             logger.info("%s: %s", k, v)
-        logger.handlers.remove(handler)
 
-    def _handle_logging(self):
+    def _setup_logging(self):
+        # Ensure these loggers have a handler so logs are actually output
+        # Without a handler, logs won't be displayed when running without a TTY (e.g., docker run without -it)
+        # We only add a handler if neither the logger nor root has any handlers configured
+        for _logger in self._get_loggers():
+            if not _logger.handlers:
+                handler = logging.StreamHandler()
+                handler.setFormatter(logging.Formatter("%(levelname)s:%(name)s:%(message)s"))
+                _logger.addHandler(handler)
+                # We need to propagate if we have the OTel handler otherwise we don't see logs shipped, in the other
+                # cases we shouldn't
+                _logger.propagate = any(isinstance(_handler, LoggingHandler) for _handler in logging.root.handlers)
+
         # do validation, we only validate logging_level because sampling_rate is handled by the sdk already
         logging_level = _LOG_LEVELS_MAP.get(self.logging_level.value)
         if logging_level is None:
@@ -121,15 +127,23 @@ def _handle_logging(self):
             return
 
         # apply logging_level changes since these are not handled by the sdk
-        logging.getLogger("opentelemetry").setLevel(logging_level)
-        logging.getLogger("elasticotel").setLevel(logging_level)
+        self.update_loggers(logging_level)
+
+    @staticmethod
+    def _get_loggers() -> list[logging.Logger]:
+        return [logging.getLogger("opentelemetry"), logging.getLogger("elasticotel")]
+
+    def update_loggers(self, logging_level: int):
+        """Update upstream and distro logging levels"""
+        for logger in self._get_loggers():
+            logger.setLevel(logging_level)
 
     def __post_init__(self):
         # we need to initialize each config item when we instantiate the Config and not at declaration time
         self.sampling_rate.init()
         self.logging_level.init()
 
-        self._handle_logging()
+        self._setup_logging()
 
 
 def _handle_logging_level(remote_config) -> ConfigUpdate:
@@ -142,10 +156,8 @@ def _handle_logging_level(remote_config) -> ConfigUpdate:
         logger.error("Logging level not handled: %s", config_logging_level)
         error_message = f"Logging level not handled: {config_logging_level}"
     else:
-        # update upstream and distro logging levels
-        logging.getLogger("opentelemetry").setLevel(logging_level)
-        logging.getLogger("elasticotel").setLevel(logging_level)
         if _config:
+            _config.update_loggers(logging_level)
             _config.logging_level.update(value=config_logging_level)
         error_message = ""
     return ConfigUpdate(error_message=error_message)

tests/distro/test_distro.py

@@ -43,6 +43,7 @@
     OTEL_TRACES_SAMPLER_ARG,
 )
 from opentelemetry import trace
+from opentelemetry.sdk._logs import LoggingHandler
 from opentelemetry.sdk.trace import sampling
 from opentelemetry._opamp.proto import opamp_pb2 as opamp_pb2
 from opentelemetry.util._once import Once
@@ -408,7 +409,102 @@ def test_configurator_does_not_log_otel_env_vars_by_default(self, logger_mock):
         logger_mock.assert_not_called()
 
 
+class TestConfig(TestCase):
+    def tearDown(self):
+        for _logger in Config._get_loggers():
+            for handler in _logger.handlers:
+                _logger.removeHandler(handler)
+            _logger.propagate = True
+
+    def test_constructor(self):
+        config = Config()
+
+        self.assertEqual(config.sampling_rate.value, "1.0")
+        self.assertEqual(config.logging_level.value, "warn")
+
+    def test_logging_setup_add_handlers_only_once(self):
+        config = Config()
+
+        self.assertTrue(logging.root.handlers)
+
+        config._setup_logging()
+
+        for _logger in config._get_loggers():
+            with self.subTest(logger=_logger):
+                self.assertEqual(len(_logger.handlers), 1)
+                self.assertFalse(_logger.propagate)
+
+        config._setup_logging()
+
+        for _logger in config._get_loggers():
+            with self.subTest(logger=_logger):
+                self.assertEqual(len(_logger.handlers), 1)
+                self.assertFalse(_logger.propagate)
+
+                # cleanup
+                _logger.removeHandler(_logger.handlers[0])
+
+    def test_logging_setup_set_propagate_true_if_sdk_logging_handler_found(self):
+        root_logger = logging.getLogger()
+        handler = LoggingHandler(logger_provider=mock.Mock())
+        root_logger.addHandler(handler)
+
+        config = Config()
+
+        config._setup_logging()
+
+        for _logger in config._get_loggers():
+            with self.subTest(logger=_logger):
+                self.assertEqual(len(_logger.handlers), 1)
+                self.assertTrue(_logger.propagate)
+
+                # cleanup
+                _logger.removeHandler(_logger.handlers[0])
+                _logger.propagate = True
+
+        root_logger.removeHandler(handler)
+
+    @mock.patch.dict(os.environ, {"OTEL_ENV": "otel", "ELASTIC_OTEL_ENV": "elastic_otel", "FOO": "foo"})
+    def test_log_env_vars_logs_configuration(self):
+        config = Config()
+        with self.assertLogs("elasticotel.distro.config", level="INFO") as cm:
+            config.log_env_vars()
+        self.assertEqual(
+            cm.output,
+            [
+                "INFO:elasticotel.distro.config:EDOT Configuration",
+                "INFO:elasticotel.distro.config:ELASTIC_OTEL_ENV: elastic_otel",
+                "INFO:elasticotel.distro.config:OTEL_ENV: otel",
+            ],
+        )
+
+    def test_to_dict(self):
+        config = Config()
+        self.assertEqual(config.to_dict(), {"logging_level": "warn", "sampling_rate": "1.0"})
+
+    @mock.patch.object(logging, "getLogger")
+    def test_update_loggers(self, get_logger_mock):
+        config = Config()
+
+        config.update_loggers(logging.WARNING)
+
+        get_logger_mock.assert_has_calls(
+            [
+                mock.call("opentelemetry"),
+                mock.call("elasticotel"),
+                mock.call().setLevel(logging.WARNING),
+                mock.call().setLevel(logging.WARNING),
+            ]
+        )
+
+
 class TestOpAMPHandler(TestCase):
+    def tearDown(self):
+        for _logger in Config._get_loggers():
+            for handler in _logger.handlers:
+                _logger.removeHandler(handler)
+            _logger.propagate = True
+
     @mock.patch.object(logging, "getLogger")
     def test_does_nothing_without_remote_config(self, get_logger_mock):
         message = opamp_pb2.ServerToAgent()
@@ -419,20 +515,20 @@ def test_does_nothing_without_remote_config(self, get_logger_mock):
         get_logger_mock.assert_not_called()
 
     @mock.patch("elasticotel.distro.config._get_config")
-    @mock.patch.object(Config, "_handle_logging")
-    @mock.patch.object(logging, "getLogger")
-    def test_ignores_non_elastic_filename(self, get_logger_mock, handle_logging_mock, get_config_mock):
-        get_config_mock.return_value = Config()
+    def test_ignores_non_elastic_filename(self, get_config_mock):
+        config = Config()
+        config.update_loggers = mock.Mock()
+        get_config_mock.return_value = config
         agent = mock.Mock()
         client = mock.Mock()
-        config = opamp_pb2.AgentConfigMap()
-        config.config_map["non-elastic"].body = json.dumps({"logging_level": "trace"}).encode()
-        config.config_map["non-elastic"].content_type = "application/json"
-        remote_config = opamp_pb2.AgentRemoteConfig(config=config, config_hash=b"1234")
+        agent_config = opamp_pb2.AgentConfigMap()
+        agent_config.config_map["non-elastic"].body = json.dumps({"logging_level": "trace"}).encode()
+        agent_config.config_map["non-elastic"].content_type = "application/json"
+        remote_config = opamp_pb2.AgentRemoteConfig(config=agent_config, config_hash=b"1234")
         message = opamp_pb2.ServerToAgent(remote_config=remote_config)
         opamp_handler(agent, client, message)
 
-        get_logger_mock.assert_not_called()
+        config.update_loggers.assert_not_called()
 
         client._update_remote_config_status.assert_called_once_with(
             remote_config_hash=b"1234", status=opamp_pb2.RemoteConfigStatuses_APPLIED, error_message=""
@@ -503,21 +599,20 @@ def test_fails_if_elastic_config_is_not_json(self, logger_mock, get_config_mock)
         client._build_full_state_message.assert_not_called()
 
     @mock.patch("elasticotel.distro.config._get_config")
-    @mock.patch.object(logging, "getLogger")
-    def test_sets_matching_logging_level(self, get_logger_mock, get_config_mock):
-        get_config_mock.return_value = Config()
+    def test_sets_matching_logging_level(self, get_config_mock):
+        config = Config()
+        config.update_loggers = mock.Mock()
+        get_config_mock.return_value = config
         agent = mock.Mock()
         client = mock.Mock()
-        config = opamp_pb2.AgentConfigMap()
-        config.config_map["elastic"].body = json.dumps({"logging_level": "trace"}).encode()
-        config.config_map["elastic"].content_type = "application/json"
-        remote_config = opamp_pb2.AgentRemoteConfig(config=config, config_hash=b"1234")
+        agent_config = opamp_pb2.AgentConfigMap()
+        agent_config.config_map["elastic"].body = json.dumps({"logging_level": "trace"}).encode()
+        agent_config.config_map["elastic"].content_type = "application/json"
+        remote_config = opamp_pb2.AgentRemoteConfig(config=agent_config, config_hash=b"1234")
         message = opamp_pb2.ServerToAgent(remote_config=remote_config)
         opamp_handler(agent, client, message)
 
-        get_logger_mock.assert_has_calls(
-            [mock.call("opentelemetry"), mock.call().setLevel(5), mock.call("elasticotel"), mock.call().setLevel(5)]
-        )
+        config.update_loggers.assert_called_once_with(5)
 
         client._update_remote_config_status.assert_called_once_with(
             remote_config_hash=b"1234", status=opamp_pb2.RemoteConfigStatuses_APPLIED, error_message=""
@@ -532,26 +627,20 @@ def test_sets_matching_logging_level(self, get_logger_mock, get_config_mock):
         client._build_full_state_message.assert_not_called()
 
     @mock.patch("elasticotel.distro.config._get_config")
-    @mock.patch.object(logging, "getLogger")
-    def test_sets_logging_to_default_info_without_logging_level_entry_in_config(self, get_logger_mock, get_config_mock):
-        get_config_mock.return_value = Config()
+    def test_sets_logging_to_default_info_without_logging_level_entry_in_config(self, get_config_mock):
+        config = Config()
+        config.update_loggers = mock.Mock()
+        get_config_mock.return_value = config
         agent = mock.Mock()
         client = mock.Mock()
-        config = opamp_pb2.AgentConfigMap()
-        config.config_map["elastic"].body = json.dumps({}).encode()
-        config.config_map["elastic"].content_type = "application/json"
-        remote_config = opamp_pb2.AgentRemoteConfig(config=config, config_hash=b"1234")
+        agent_config = opamp_pb2.AgentConfigMap()
+        agent_config.config_map["elastic"].body = json.dumps({}).encode()
+        agent_config.config_map["elastic"].content_type = "application/json"
+        remote_config = opamp_pb2.AgentRemoteConfig(config=agent_config, config_hash=b"1234")
         message = opamp_pb2.ServerToAgent(remote_config=remote_config)
         opamp_handler(agent, client, message)
 
-        get_logger_mock.assert_has_calls(
-            [
-                mock.call("opentelemetry"),
-                mock.call().setLevel(logging.WARNING),
-                mock.call("elasticotel"),
-                mock.call().setLevel(logging.WARNING),
-            ]
-        )
+        config.update_loggers.assert_called_once_with(logging.WARNING)
 
         client._update_remote_config_status.assert_called_once_with(
             remote_config_hash=b"1234", status=opamp_pb2.RemoteConfigStatuses_APPLIED, error_message=""