Fix logging without a tty

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=""