logs: `Overriding of current EventLoggerProvider is not allowed`

[aborigeth]

Describe your environment

OS: Debian 12
Python version: 3.13
SDK version: 1.28.2
API version: 0.49b2

What happened?

Warnings and significant delay at the startup:

Overriding of current EventLoggerProvider is not allowed

opentelemetry-python/opentelemetry-api/src/opentelemetry/_events/__init__.py

Lines 196 to 198 in db4ef06

	_logger.warning(
	"Overriding of current EventLoggerProvider is not allowed"
	)

Timeout was exceeded in force_flush().

opentelemetry-python/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/export/__init__.py

Lines 376 to 377 in db4ef06

	if not ret:
	_logger.warning("Timeout was exceeded in force_flush().")

Steps to Reproduce

pip install opentelemetry-distro[otlp] opentelemetry-instrumentation
opentelemetry-bootstrap -a install

OTEL_LOGS_EXPORTER=console,otlp
OTEL_PYTHON_LOGGING_AUTO_INSTRUMENTATION_ENABLED=true

Expected Result

No warnings

Actual Result

Warnings and delay

Additional context

Probalby regression in 0.49b2 version
#4270

Would you like to implement a fix?

None

[xrmx]

What does "significant delay at startup" mean? The warning is harmless and has already been fixed in #4299

[aborigeth]

What does "significant delay at startup" mean?

About 30 seconds till application starts

[aborigeth]

Timeout was exceeded in force_flush(). happens due to uvicorn, otherwise it works fine.

[lzchen]

@aborigeth

Seems like the error message Overriding of current EventLoggerProvider is not allowed might not be related to the delay in application start.

Could you paste a code snippet of what you are instrumenting?

[aborigeth]

Seems like the error message Overriding of current EventLoggerProvider is not allowed might not be related to the delay in application start.

Yes, delay caused by something else, maybe fastapi/uvicorn implementation.

Could you paste a code snippet of what you are instrumenting?

uvicorn==0.28.1
fastapi==0.110.3
opentelemetry-api==1.28.2
opentelemetry-distro==0.49b2
opentelemetry-exporter-otlp==1.28.2
opentelemetry-exporter-otlp-proto-common==1.28.2
opentelemetry-exporter-otlp-proto-grpc==1.28.2
opentelemetry-exporter-otlp-proto-http==1.28.2
opentelemetry-instrumentation==0.49b2
opentelemetry-proto==1.28.2
opentelemetry-sdk==1.28.2
opentelemetry-semantic-conventions==0.49b2

main.py:

from fastapi import FastAPI

app = FastAPI()


@app.get("/")
async def root():
    return {"message": "Hello World"}

opentelemetry-instrument uvicorn main:app

{
    "body": "Overriding of current EventLoggerProvider is not allowed",
    "severity_number": "<SeverityNumber.WARN: 13>",
    "severity_text": "WARN",
    "attributes": {
        "code.filepath": "/usr/local/lib/python3.13/site-packages/opentelemetry/_events/__init__.py",
        "code.function": "_set_event_logger_provider",
        "code.lineno": 196
    },
    "dropped_attributes": 0,
    "timestamp": "2024-12-04T08:03:33.858802Z",
    "observed_timestamp": "2024-12-04T08:03:33.858842Z",
    "trace_id": "0x00000000000000000000000000000000",
    "span_id": "0x0000000000000000",
    "trace_flags": 0,
    "resource": {
        "attributes": {
            "telemetry.sdk.language": "python",
            "telemetry.sdk.name": "opentelemetry",
            "telemetry.sdk.version": "1.28.2",
            "service.name": "api",
            "telemetry.auto.version": "0.49b2"
        },
        "schema_url": ""
    }
}
{
    "body": "Timeout was exceeded in force_flush().",
    "severity_number": "<SeverityNumber.WARN: 13>",
    "severity_text": "WARN",
    "attributes": {
        "otelSpanID": "0",
        "otelTraceID": "0",
        "otelTraceSampled": false,
        "otelServiceName": "api",
        "code.filepath": "/usr/local/lib/python3.13/site-packages/opentelemetry/sdk/_logs/_internal/export/__init__.py",
        "code.function": "force_flush",
        "code.lineno": 377
    },
    "dropped_attributes": 0,
    "timestamp": "2024-12-04T08:04:04.929736Z",
    "observed_timestamp": "2024-12-04T08:04:04.929906Z",
    "trace_id": "0x00000000000000000000000000000000",
    "span_id": "0x0000000000000000",
    "trace_flags": 0,
    "resource": {
        "attributes": {
            "telemetry.sdk.language": "python",
            "telemetry.sdk.name": "opentelemetry",
            "telemetry.sdk.version": "1.28.2",
            "service.name": "api",
            "telemetry.auto.version": "0.49b2"
        },
        "schema_url": ""
    }
}

[xrmx]

@aborigeth How you are exporting logs? It looks like you setup to send otlp and console but the otlp receiver is not there?

[aborigeth]

@aborigeth How you are exporting logs? It looks like you setup to send otlp and console but the otlp receiver is not there?

OTEL_EXPORTER_OTLP_ENDPOINT="https://opentelemetry-collector.example.com"
OTEL_EXPORTER_OTLP_HEADERS="Authorization=Basic%20XXXX"

As I mentioned above, instrumentation and export works fine (apart from EventLoggerProvider warning) in regular Python application.
But when I start FastAPI with uvicorn - delay appears.

[mats-ruell]

Following because I have the exact same issue.

[xrmx]

Following because I have the exact same issue.

@mats-ruell Which one?

[mats-ruell]

Following because I have the exact same issue.

@mats-ruell Which one?

{
    "body": "Overriding of current EventLoggerProvider is not allowed",
    "severity_number": "<SeverityNumber.WARN: 13>",
    "severity_text": "WARN",
    "attributes": {
        "code.filepath": "/Users/matsruell/Documents/XXX/XXX/.venv/lib/python3.12/site-packages/opentelemetry/_events/__init__.py",
        "code.function": "_set_event_logger_provider",
        "code.lineno": 196
    },
    "dropped_attributes": 0,
    "timestamp": "2024-12-09T16:36:51.155139Z",
    "observed_timestamp": "2024-12-09T16:36:51.155165Z",
    "trace_id": "0x00000000000000000000000000000000",
    "span_id": "0x0000000000000000",
    "trace_flags": 0,
    "resource": {
        "attributes": {
            "telemetry.sdk.language": "python",
            "telemetry.sdk.name": "opentelemetry",
            "telemetry.sdk.version": "1.28.2",
            "service.name": "XXX",
            "telemetry.auto.version": "0.49b2"
        },
        "schema_url": ""
    }
}
{
    "body": "Timeout was exceeded in force_flush().",
    "severity_number": "<SeverityNumber.WARN: 13>",
    "severity_text": "WARN",
    "attributes": {
        "otelSpanID": "0",
        "otelTraceID": "0",
        "otelTraceSampled": false,
        "otelServiceName": "XXX",
        "code.filepath": "/Users/matsruell/Documents/XXX/XXX/.venv/lib/python3.12/site-packages/opentelemetry/sdk/_logs/_internal/export/__init__.py",
        "code.function": "force_flush",
        "code.lineno": 377
    },
    "dropped_attributes": 0,
    "timestamp": "2024-12-09T16:37:21.610859Z",
    "observed_timestamp": "2024-12-09T16:37:21.612145Z",
    "trace_id": "0x00000000000000000000000000000000",
    "span_id": "0x0000000000000000",
    "trace_flags": 0,
    "resource": {
        "attributes": {
            "telemetry.sdk.language": "python",
            "telemetry.sdk.name": "opentelemetry",
            "telemetry.sdk.version": "1.28.2",
            "service.name": "XXX",
            "telemetry.auto.version": "0.49b2"
        },
        "schema_url": ""
    }
}

These are my environment variables:

OTEL_PYTHON_LOGGING_AUTO_INSTRUMENTATION_ENABLED='true'
OTEL_PYTHON_LOG_FORMAT='[trace_id=%(otelTraceID)s] %(message)s'
OTEL_PYTHON_LOG_LEVEL='DEBUG'
OTEL_PYTHON_LOG_CORRELATION='true'
OTEL_EXPORTER_OTLP_ENDPOINT='http://localhost:32095'
OTEL_EXPORTER_OTLP_PROTOCOL='http/protobuf'
OTEL_PYTHON_REQUESTS_EXCLUDED_URLS='/tokenizer.json,mermaid'
OTEL_PYTHON_URLLIB3_EXCLUDED_URLS='/tokenizer.json,mermaid'
OTEL_PYTHON_EXCLUDED_URLS='client/.*/info'
OTEL_PYTHON_DISABLED_INSTRUMENTATIONS='grpc_aio_client,grpc_aio_server,grpc_client,grpc_server'
OTEL_SERVICE_NAME='XXX'
OTEL_TRACES_EXPORTER='otlp'
OTEL_METRICS_EXPORTER='otlp'
OTEL_LOGS_EXPORTER='console,otlp'

Traces and metrics both work perfectly. I am not getting logs in either console or otlp endpoint. It is also a FastAPI application.

[folt]

I have the same problem

My config _OTelSDKConfigurator

class OtelSettings(PydanticSettings):
    model_config = SettingsConfigDict(env_prefix="OTEL_")

    def setup_otel(self):
        for key, value in self.model_dump(by_alias=True).items():
            env_key = f"OTEL_{key.upper()}"
            os.environ[env_key] = str(value)

    SDK_DISABLED: bool = False
    RESOURCE_ATTRIBUTES: str = ""
    LOG_LEVEL: str = "info"
    SERVICE_NAME: str = "unknown-app"
    PYTHON_LOGGING_AUTO_INSTRUMENTATION_ENABLED: bool = True
    PYTHON_ASYNCIO_FUTURE_TRACE_ENABLED: bool = True

    BLRP_SCHEDULE_DELAY: int = 5000
    BLRP_EXPORT_TIMEOUT: int = 30000
    BLRP_MAX_QUEUE_SIZE: int = 2048
    BLRP_MAX_EXPORT_BATCH_SIZE: int = 512

    BSP_SCHEDULE_DELAY: int = 5000
    BSP_EXPORT_TIMEOUT: int = 30000
    BSP_MAX_QUEUE_SIZE: int = 2048
    BSP_MAX_EXPORT_BATCH_SIZE: int = 512

    EXPORTER_JAEGER_AGENT_PORT: int = 6831
    EXPORTER_JAEGER_TIMEOUT: int = 10
    EXPORTER_JAEGER_GRPC_INSECURE: bool = True

    EXPORTER_OTLP_TRACES_TIMEOUT: int = 10
    EXPORTER_OTLP_TRACES_INSECURE: bool = True
    EXPORTER_OTLP_TRACES_PROTOCOL: str = "grpc"

    EXPORTER_OTLP_LOGS_TIMEOUT: int = 10
    EXPORTER_OTLP_LOGS_INSECURE: bool = True
    EXPORTER_OTLP_LOGS_PROTOCOL: str = "grpc"

    EXPORTER_OTLP_METRICS_TIMEOUT: int = 10
    EXPORTER_OTLP_METRICS_INSECURE: bool = True
    EXPORTER_OTLP_METRICS_PROTOCOL: str = "grpc"

    LOGS_EXPORTER: str = "otlp"
    METRICS_EXPORTER: str = "otlp"
    TRACES_EXPORTER: str = "otlp"

    EXPORTER_PROMETHEUS_PORT: int = 9464

    EXPERIMENTAL_RESOURCE_DETECTORS: str = "sdk,host,os,process,container,env"

    PYTHON_GRPC_EXCLUDED_SERVICES: str = "grpc.health.v1.Health"

    @computed_field(alias="EXPORTER_JAEGER_AGENT_HOST")
    def exporter_jaeger_agent_host(self) -> str:
        host = PRD_HOST if os.environ.get("ENVIRONMENT", "local") == "prd" else STG_HOST
        return f"{host}"

    @computed_field(alias="EXPORTER_JAEGER_ENDPOINT")
    def exporter_jaeger_endpoint(self) -> str:
        host = PRD_HOST if os.environ.get("ENVIRONMENT", "local") == "prd" else STG_HOST
        return f"{host}:14250"

    @computed_field(alias="EXPORTER_OTLP_ENDPOINT")
    def exporter_otlp_endpoint(self) -> str:
        host = PRD_HOST if os.environ.get("ENVIRONMENT", "local") == "prd" else STG_HOST
        return f"{host}:4317"

    @computed_field(alias="EXPORTER_OTLP_TRACES_ENDPOINT")
    def exporter_otlp_traces_endpoint(self) -> str:
        host = PRD_HOST if os.environ.get("ENVIRONMENT", "local") == "prd" else STG_HOST
        return f"{host}:4317"

    @computed_field(alias="EXPORTER_OTLP_LOGS_ENDPOINT")
    def exporter_otlp_logs_endpoint(self) -> str:
        host = PRD_HOST if os.environ.get("ENVIRONMENT", "local") == "prd" else STG_HOST
        return f"{host}:4317"

    @computed_field(alias="EXPORTER_OTLP_METRICS_ENDPOINT")
    def exporter_otlp_metrics_endpoint(self) -> str:
        host = PRD_HOST if os.environ.get("ENVIRONMENT", "local") == "prd" else STG_HOST
        return f"{host}:4317"

    @computed_field(alias="EXPORTER_PROMETHEUS_HOST")
    def exporter_prometheus_host(self) -> str:
        host = PRD_HOST if os.environ.get("ENVIRONMENT", "local") == "prd" else STG_HOST
        return f"{host}"

logs:

{
   "body":"Overriding of current EventLoggerProvider is not allowed",
   "severity":"WARN",
   "attributes":{
      "code.filepath":"/backend/venv/lib/python3.11/site-packages/opentelemetry/_events/__init__.py",
      "code.function":"_set_event_logger_provider",
      "code.lineno":196
   },
   "resources":{
      "deployment.environment":"stg",
      "host.arch":"x86_64",
      "host.name":"cf049a004515",
      "os.type":"linux",
      "os.version":"6.1.0-17-amd64",
      "process.command":"-m",
      "process.command_args":[
         "-m"
      ],
      "process.command_line":"-m",
      "process.executable.name":"/backend/venv/bin/python",
      "process.executable.path":"/backend/venv/bin",
      "process.parent_pid":0,
      "process.pid":1,
      "process.runtime.description":"3.11.9 (main, Sep  4 2024, 23:13:27) [GCC 10.2.1 20210110]",
      "process.runtime.name":"cpython",
      "process.runtime.version":"3.11.9",
      "service.name":"mspy-auth",
      "telemetry.auto.version":"0.49b2",
      "telemetry.sdk.language":"python",
      "telemetry.sdk.name":"libpy-otel",
      "telemetry.sdk.version":"0.1.54"
   },
   "instrumentation_scope":{
      "name":"opentelemetry._events"
   }
}