Handle log level change from environment variable (#397)

* distro: introduce handling of ELASTIC_OTEL_LOG_LEVEL

That this our version of OTEL_LOG_LEVEL with the values supported by the
central config logging_level setting.

* Fix default logging level

* Update configuration docs

* Add tests

* Please pyright

* Always set the logging level

* Update docs/reference/edot-python/configuration.md

* Update docs/reference/edot-python/configuration.md

* Switch to OTEL_LOG_LEVEL

---------

Co-authored-by: Fabrizio Ferri-Benedetti <[email protected]>

Author: xrmx

docs/reference/edot-python/configuration.md

@@ -90,23 +90,27 @@ EDOT Python uses different defaults than OpenTelemetry Python for the following
 | Option | EDOT Python default | OpenTelemetry Python default |
 |---|---|---|
 | `OTEL_EXPERIMENTAL_RESOURCE_DETECTORS` | `process_runtime,os,otel,telemetry_distro,service_instance,containerid,_gcp,aws_ec2,aws_ecs,aws_elastic_beanstalk,azure_app_service,azure_vm` | `otel` |
-| `OTEL_METRICS_EXEMPLAR_FILTER` | `always_off` | `trace_based` |
 | `OTEL_EXPORTER_OTLP_METRICS_TEMPORALITY_PREFERENCE` | `DELTA` | `CUMULATIVE` |
+| `OTEL_LOG_LEVEL` | `warn` | Not handled |
+| `OTEL_METRICS_EXEMPLAR_FILTER` | `always_off` | `trace_based` |
 | `OTEL_TRACES_SAMPLER` | `parentbased_traceidratio` | `parentbased_always_on` |
 | `OTEL_TRACES_SAMPLER_ARG` | `1.0` | |
 
 :::{note}
 `OTEL_EXPERIMENTAL_RESOURCE_DETECTORS` cloud resource detectors are dynamically set. When running in a Kubernetes Pod it will be set to `process_runtime,os,otel,telemetry_distro,service_instance,_gcp,aws_eks`.
 :::
 
+:::{note}
+`OTEL_LOG_LEVEL` accepts the following levels: `trace`, `debug`, `info`, `warn`, `error`, `fatal`, `off`.
+:::
 
 ### Configuration options only available in EDOT Python
 
 `ELASTIC_OTEL_` options are specific to Elastic and will always live in EDOT Python include the following.
 
 | Option(s) | Default | Description |
 |---|---|---|
-| `ELASTIC_OTEL_SYSTEM_METRICS_ENABLED` | `false` | When sets to `true`, sends *system namespace* metrics. |
+| `ELASTIC_OTEL_SYSTEM_METRICS_ENABLED` | `false` | When set to `true`, sends *system namespace* metrics. |
 
 ## LLM settings
 

src/elasticotel/distro/__init__.py

@@ -53,9 +53,12 @@
 from opentelemetry._opamp.proto import opamp_pb2 as opamp_pb2
 
 from elasticotel.distro import version
-from elasticotel.distro.environment_variables import ELASTIC_OTEL_OPAMP_ENDPOINT, ELASTIC_OTEL_SYSTEM_METRICS_ENABLED
+from elasticotel.distro.environment_variables import (
+    ELASTIC_OTEL_OPAMP_ENDPOINT,
+    ELASTIC_OTEL_SYSTEM_METRICS_ENABLED,
+)
 from elasticotel.distro.resource_detectors import get_cloud_resource_detectors
-from elasticotel.distro.config import opamp_handler, DEFAULT_SAMPLING_RATE
+from elasticotel.distro.config import opamp_handler, DEFAULT_SAMPLING_RATE, _initialize_config
 
 
 logger = logging.getLogger(__name__)
@@ -88,6 +91,9 @@ def _configure(self, **kwargs):
         }
         super()._configure(**kwargs)
 
+        # set our local config based on environment variables
+        _initialize_config()
+
         enable_opamp = False
         endpoint = os.environ.get(ELASTIC_OTEL_OPAMP_ENDPOINT)
         if endpoint:

src/elasticotel/distro/config.py

@@ -17,15 +17,16 @@
 from __future__ import annotations
 
 import logging
+import os
 from dataclasses import dataclass
 
 from opentelemetry import trace
-
-from opentelemetry.sdk.trace.sampling import ParentBasedTraceIdRatio
 from opentelemetry._opamp import messages
 from opentelemetry._opamp.agent import OpAMPAgent
 from opentelemetry._opamp.client import OpAMPClient
 from opentelemetry._opamp.proto import opamp_pb2 as opamp_pb2
+from opentelemetry.sdk.environment_variables import OTEL_LOG_LEVEL, OTEL_TRACES_SAMPLER_ARG
+from opentelemetry.sdk.trace.sampling import ParentBasedTraceIdRatio
 
 
 logger = logging.getLogger(__name__)
@@ -41,33 +42,69 @@
 }
 
 DEFAULT_SAMPLING_RATE = 1.0
-DEFAULT_LOGGING_LEVEL = "info"
+DEFAULT_LOGGING_LEVEL = "warn"
 
 LOGGING_LEVEL_CONFIG_KEY = "logging_level"
 SAMPLING_RATE_CONFIG_KEY = "sampling_rate"
 
+_config: Config | None = None
+
 
-@dataclass
 class ConfigItem:
-    value: str
+    def __init__(self, default: str, from_env_var: str | None = None):
+        self._default = default
+        self._env_var = from_env_var
+
+    def init(self):
+        if self._env_var is not None:
+            value = os.environ.get(self._env_var, self._default)
+        else:
+            value = self._default
+        self.value = value
+
+    def update(self, value: str):
+        """Update value"""
+        self.value = value
+
+    def reset(self) -> str:
+        """Value is not good, reset to default"""
+        self.value = self._default
+        return self.value
 
 
 @dataclass
 class ConfigUpdate:
     error_message: str = ""
 
 
-# TODO: this should grow into a proper configuration store initialized from env vars and so on
+# TODO: this should grow into a proper configuration store in the OpenTelemetry SDK
 @dataclass
 class Config:
-    sampling_rate = ConfigItem(value=str(DEFAULT_SAMPLING_RATE))
-    logging_level = ConfigItem(value=DEFAULT_LOGGING_LEVEL)
+    sampling_rate = ConfigItem(default=str(DEFAULT_SAMPLING_RATE), from_env_var=OTEL_TRACES_SAMPLER_ARG)
+    # currently the sdk does not handle OTEL_LOG_LEVEL, so we use handle it on our own
+    logging_level = ConfigItem(default=DEFAULT_LOGGING_LEVEL, from_env_var=OTEL_LOG_LEVEL)
 
     def to_dict(self):
         return {LOGGING_LEVEL_CONFIG_KEY: self.logging_level.value, SAMPLING_RATE_CONFIG_KEY: self.sampling_rate.value}
 
+    def _handle_logging(self):
+        # 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:
+            logger.error("Logging level not handled: %s", self.logging_level.value)
+            self.logging_level.reset()
+            return
 
-_config = Config()
+        # apply logging_level changes since these are not handled by the sdk
+        logging.getLogger("opentelemetry").setLevel(logging_level)
+        logging.getLogger("elasticotel").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()
 
 
 def _handle_logging_level(remote_config) -> ConfigUpdate:
@@ -83,7 +120,8 @@ def _handle_logging_level(remote_config) -> ConfigUpdate:
         # update upstream and distro logging levels
         logging.getLogger("opentelemetry").setLevel(logging_level)
         logging.getLogger("elasticotel").setLevel(logging_level)
-        _config.logging_level = ConfigItem(value=config_logging_level)
+        if _config:
+            _config.logging_level.update(value=config_logging_level)
         error_message = ""
     return ConfigUpdate(error_message=error_message)
 
@@ -118,14 +156,22 @@ def _handle_sampling_rate(remote_config) -> ConfigUpdate:
         root_sampler._rate = sampling_rate  # type: ignore[reportAttributeAccessIssue]
         root_sampler._bound = root_sampler.get_bound_for_rate(root_sampler._rate)  # type: ignore[reportAttributeAccessIssue]
         logger.debug("Updated sampler rate to %s", sampling_rate)
-        _config.sampling_rate = ConfigItem(value=config_sampling_rate)
+        if _config:
+            _config.sampling_rate.update(value=config_sampling_rate)
     return ConfigUpdate()
 
 
 def _report_full_state(message: opamp_pb2.ServerToAgent):
     return message.flags & opamp_pb2.ServerToAgentFlags_ReportFullState
 
 
+def _initialize_config():
+    """This is called by the SDK Configurator"""
+    global _config
+    _config = Config()
+    return _config
+
+
 def _get_config():
     global _config
     return _config
@@ -164,8 +210,9 @@ def opamp_handler(agent: OpAMPAgent, client: OpAMPClient, message: opamp_pb2.Ser
     )
 
     # update the cached effective config with what we updated
-    effective_config = {"elastic": _config.to_dict()}
-    client._update_effective_config(effective_config)
+    if _config:
+        effective_config = {"elastic": _config.to_dict()}
+        client._update_effective_config(effective_config)
 
     # if we changed the config send an ack to the server so we don't receive the same config at every heartbeat response
     if updated_remote_config is not None:

tests/distro/test_distro.py

@@ -235,6 +235,41 @@ def test_configurator_ignores_opamp_without_endpoint(self, client_mock, agent_mo
         client_mock.assert_not_called()
         agent_mock.assert_not_called()
 
+    @mock.patch.dict("os.environ", {"OTEL_LOG_LEVEL": "debug"}, clear=True)
+    @mock.patch("elasticotel.distro.config.logger")
+    def test_configurator_applies_elastic_otel_log_level(self, logger_mock):
+        ElasticOpenTelemetryConfigurator()._configure()
+
+        logger_mock.error.assert_not_called()
+
+        self.assertEqual(logging.getLogger("opentelemetry").getEffectiveLevel(), logging.DEBUG)
+        self.assertEqual(logging.getLogger("elasticotel").getEffectiveLevel(), logging.DEBUG)
+
+    @mock.patch.dict("os.environ", {}, clear=True)
+    @mock.patch("elasticotel.distro.config.logger")
+    def test_configurator_handles_elastic_otel_log_level_not_set(self, logger_mock):
+        ElasticOpenTelemetryConfigurator()._configure()
+
+        logger_mock.error.assert_not_called()
+
+        self.assertEqual(logging.getLogger("opentelemetry").getEffectiveLevel(), logging.WARNING)
+        self.assertEqual(logging.getLogger("elasticotel").getEffectiveLevel(), logging.WARNING)
+
+    @mock.patch.dict("os.environ", {"OTEL_LOG_LEVEL": "invalid"}, clear=True)
+    def test_configurator_handles_invalid_elastic_otel_log_level(self):
+        with self.assertLogs("elasticotel", level="ERROR") as cm:
+            ElasticOpenTelemetryConfigurator()._configure()
+
+        self.assertEqual(
+            cm.output,
+            [
+                "ERROR:elasticotel.distro.config:Logging level not handled: invalid",
+            ],
+        )
+
+        self.assertEqual(logging.getLogger("opentelemetry").getEffectiveLevel(), logging.WARNING)
+        self.assertEqual(logging.getLogger("elasticotel").getEffectiveLevel(), logging.WARNING)
+
 
 class TestOpAMPHandler(TestCase):
     @mock.patch.object(logging, "getLogger")
@@ -247,8 +282,9 @@ 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, get_config_mock):
+    def test_ignores_non_elastic_filename(self, get_logger_mock, handle_logging_mock, get_config_mock):
         get_config_mock.return_value = Config()
         agent = mock.Mock()
         client = mock.Mock()
@@ -265,7 +301,7 @@ def test_ignores_non_elastic_filename(self, get_logger_mock, get_config_mock):
             remote_config_hash=b"1234", status=opamp_pb2.RemoteConfigStatuses_APPLIED, error_message=""
         )
         client._update_effective_config.assert_called_once_with(
-            {"elastic": {"logging_level": "info", "sampling_rate": "1.0"}}
+            {"elastic": {"logging_level": "warn", "sampling_rate": "1.0"}}
         )
         client._build_remote_config_status_response_message.assert_called_once_with(
             client._update_remote_config_status()
@@ -318,17 +354,17 @@ def test_sets_logging_to_default_info_without_logging_level_entry_in_config(self
         get_logger_mock.assert_has_calls(
             [
                 mock.call("opentelemetry"),
-                mock.call().setLevel(logging.INFO),
+                mock.call().setLevel(logging.WARNING),
                 mock.call("elasticotel"),
-                mock.call().setLevel(logging.INFO),
+                mock.call().setLevel(logging.WARNING),
             ]
         )
 
         client._update_remote_config_status.assert_called_once_with(
             remote_config_hash=b"1234", status=opamp_pb2.RemoteConfigStatuses_APPLIED, error_message=""
         )
         client._update_effective_config.assert_called_once_with(
-            {"elastic": {"logging_level": "info", "sampling_rate": "1.0"}}
+            {"elastic": {"logging_level": "warn", "sampling_rate": "1.0"}}
         )
         client._build_remote_config_status_response_message.assert_called_once_with(
             client._update_remote_config_status()
@@ -356,7 +392,7 @@ def test_warns_if_logging_level_does_not_match_our_map(self, get_logger_mock, ge
             client._update_remote_config_status()
         )
         client._update_effective_config.assert_called_once_with(
-            {"elastic": {"logging_level": "info", "sampling_rate": "1.0"}}
+            {"elastic": {"logging_level": "warn", "sampling_rate": "1.0"}}
         )
         agent.send.assert_called_once_with(payload=mock.ANY)
         client._build_full_state_message.assert_not_called()
@@ -382,7 +418,7 @@ def test_sets_matching_sampling_rate(self, get_tracer_provider_mock, get_config_
             remote_config_hash=b"1234", status=opamp_pb2.RemoteConfigStatuses_APPLIED, error_message=""
         )
         client._update_effective_config.assert_called_once_with(
-            {"elastic": {"logging_level": "info", "sampling_rate": "0.5"}}
+            {"elastic": {"logging_level": "warn", "sampling_rate": "0.5"}}
         )
         client._build_remote_config_status_response_message.assert_called_once_with(
             client._update_remote_config_status()
@@ -413,7 +449,7 @@ def test_sets_sampling_rate_to_default_info_without_sampling_rate_entry_in_confi
             remote_config_hash=b"1234", status=opamp_pb2.RemoteConfigStatuses_APPLIED, error_message=""
         )
         client._update_effective_config.assert_called_once_with(
-            {"elastic": {"logging_level": "info", "sampling_rate": "1.0"}}
+            {"elastic": {"logging_level": "warn", "sampling_rate": "1.0"}}
         )
         client._build_remote_config_status_response_message.assert_called_once_with(
             client._update_remote_config_status()
@@ -447,7 +483,7 @@ def test_warns_if_sampling_rate_value_is_invalid(self, get_tracer_provider_mock,
             error_message="Invalid sampling_rate unexpected",
         )
         client._update_effective_config.assert_called_once_with(
-            {"elastic": {"logging_level": "info", "sampling_rate": "1.0"}}
+            {"elastic": {"logging_level": "warn", "sampling_rate": "1.0"}}
         )
         client._build_remote_config_status_response_message.assert_called_once_with(
             client._update_remote_config_status()
@@ -479,7 +515,7 @@ def test_warns_if_sampler_is_not_what_we_expect(self, get_tracer_provider_mock,
             remote_config_hash=b"1234", status=opamp_pb2.RemoteConfigStatuses_APPLIED, error_message=""
         )
         client._update_effective_config.assert_called_once_with(
-            {"elastic": {"logging_level": "info", "sampling_rate": "1.0"}}
+            {"elastic": {"logging_level": "warn", "sampling_rate": "1.0"}}
         )
         client._build_remote_config_status_response_message.assert_called_once_with(
             client._update_remote_config_status()
@@ -508,7 +544,7 @@ def test_ignores_tracer_provider_without_a_sampler(self, get_tracer_provider_moc
             remote_config_hash=b"1234", status=opamp_pb2.RemoteConfigStatuses_APPLIED, error_message=""
         )
         client._update_effective_config.assert_called_once_with(
-            {"elastic": {"logging_level": "info", "sampling_rate": "1.0"}}
+            {"elastic": {"logging_level": "warn", "sampling_rate": "1.0"}}
         )
         client._build_remote_config_status_response_message.assert_called_once_with(
             client._update_remote_config_status()