diff --git a/src/elasticotel/distro/config.py b/src/elasticotel/distro/config.py index ab3759d..ad3aef8 100644 --- a/src/elasticotel/distro/config.py +++ b/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) diff --git a/tests/distro/test_distro.py b/tests/distro/test_distro.py index 4746fad..e59d14a 100644 --- a/tests/distro/test_distro.py +++ b/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=""