Infinite loop through exporter, when using OTLPLogExporter

[4c0n]

Describe your environment

OS: Debian Python Docker Image
Python version: 3.13
SDK version: 1.35.0
API version: N/A

What happened?

We setup our log exporting as follows:

resource = Resource(attributes={SERVICE_NAME: "otel-service"})
logger_provider = LoggerProvider(resource=resource)
logger_provider.add_log_record_processor(BatchLogRecordProcessor(OTLPLogExporter()))
set_logger_provider(logger_provider)

logging_handler = LoggingHandler(level=logging.NOTSET, logger_provider=logger_provider)

logger = logging.getLogger()
logger.addHandler(logging_handler)
logger.setLevel(settings.log_level)

Now when exporting the logs fails because it is not possible to connect to the collector, we end up in an infinite loop type situation. This is caused by the mixin here:

opentelemetry-python/exporter/opentelemetry-exporter-otlp-proto-grpc/src/opentelemetry/exporter/otlp/proto/grpc/exporter.py

Line 340 in ad266aa

logger.error(

which tries to log the fact that exporting the logs failed.

The mixin is used by OTLPLogExporter: https://github.com/open-telemetry/opentelemetry-python/blob/v1.35.0/exporter/opentelemetry-exporter-otlp-proto-grpc/src/opentelemetry/exporter/otlp/proto/grpc/_log_exporter/__init__.py

Steps to Reproduce

Set up logging as described above and make sure there is no collector running to export the logs to.

Expected Result

Not quite sure, at least not a hanging application that is stuck in this infinite loop.

Actual Result

An infinite loop.

Additional context

No response

Would you like to implement a fix?

Yes

[aabmass]

@4c0n is there actually an infinite loop or are you just seeing repeated logs asynchronously?

[4c0n]

There are no logs to be seen as they cannot be exported and then logging that the logs cannot be exported does not work as it would get exported again which fails.
Hope I'm explaining this clear enough...

[emdneto]

@4c0n maybe duplicated of #2701 ?

[aabmass]

Expected Result

Not quite sure, at least not a hanging application that is stuck in this infinite loop.

Actual Result

An infinite loop.

I will try your repro. It's inevitable that errors create a feedback loop but I would expect it to intermittent and not cause hanging

[4c0n]

@aabmass Thanks! There are ways to prevent it I think. For example, one of them is not using this mixin for the OTLPLogExporter but using a different implementation there that does not try to log that logging failed, that way the inevitable quickly becomes evitable ;)
It's also possible to remove the failing handler from the root logger before logging that logging failed and it might even be possible to add back the handler once that is done.
I'm sure there are other ways as well.

Can you see any objections to such approaches?

[DylanRussell]

Raised #4695

[aabmass]

I'm not able to reproduce what you mean by infinite loop or hanging. I tried your repro and it exits after ~8s when the retry backoff in the exporter is done. (I added a basicConfig so you can see what's happening)

$ time uv run repro.py
INFO:root:Hello, world!
WARNING:opentelemetry.exporter.otlp.proto.grpc.exporter:Transient error StatusCode.UNAVAILABLE encountered while exporting logs to localhost:4317, retrying in 1.13s.
WARNING:opentelemetry.exporter.otlp.proto.grpc.exporter:Transient error StatusCode.UNAVAILABLE encountered while exporting logs to localhost:4317, retrying in 2.37s.
WARNING:opentelemetry.exporter.otlp.proto.grpc.exporter:Transient error StatusCode.UNAVAILABLE encountered while exporting logs to localhost:4317, retrying in 3.98s.
ERROR:opentelemetry.exporter.otlp.proto.grpc.exporter:Failed to export logs to localhost:4317, error code: StatusCode.UNAVAILABLE

real    0m7.789s
user    0m0.204s
sys     0m0.125s

Repro Script

# /// script
# requires-python = ">=3.13"
# dependencies = [
#  "opentelemetry-api==1.35.0",
#  "opentelemetry-exporter-otlp-proto-grpc==1.35.0",
# ]
# ///
import logging

from opentelemetry._logs import set_logger_provider
from opentelemetry.exporter.otlp.proto.grpc._log_exporter import (
    OTLPLogExporter,
)
from opentelemetry.sdk._logs import LoggerProvider, LoggingHandler
from opentelemetry.sdk._logs.export import BatchLogRecordProcessor
from opentelemetry.sdk.resources import SERVICE_NAME, Resource

resource = Resource(attributes={SERVICE_NAME: "otel-service"})
logger_provider = LoggerProvider(resource=resource)
logger_provider.add_log_record_processor(
    BatchLogRecordProcessor(OTLPLogExporter())
)
set_logger_provider(logger_provider)

logging_handler = LoggingHandler(
    level=logging.NOTSET, logger_provider=logger_provider
)

logger = logging.getLogger()
logging.basicConfig(level=logging.INFO)
logger.addHandler(logging_handler)
logger.setLevel(logging.INFO)


logger.info("Hello, world!")

If you're encountering something different, could you please share runnable minimal repro?

There are no logs to be seen as they cannot be exported and then logging that the logs cannot be exported does not work as it would get exported again which fails.

I still don't think this is a bug, I would like to hear your perspective more on this. For example, if the OTLP endpoint you are trying to send to is down for 5 minutes or you temporarily exceeded your quota and get RESOURCE_EXHAUSTED, the logs from the OTLP exporter would be helpful.

[emdneto]

@aabmass can you please try this?

# /// script
# requires-python = ">=3.13"
# dependencies = [
#     "fastapi",
#     "opentelemetry-api",
#     "opentelemetry-sdk",
#     "opentelemetry-distro",
#     "opentelemetry-instrumentation",
#     "opentelemetry-exporter-otlp",
#     "uvicorn",
#     "opentelemetry-instrumentation-fastapi",
#     "opentelemetry-instrumentation-asgi",
#     "opentelemetry-util-http",
#     "opentelemetry-semantic-conventions",
# ]
# ///

import os
import logging
logging.basicConfig(level=0)
os.environ["OTEL_PYTHON_LOGGING_AUTO_INSTRUMENTATION_ENABLED"] = "true"

from opentelemetry.instrumentation import auto_instrumentation

auto_instrumentation.initialize()

import uvicorn

from fastapi import FastAPI

app = FastAPI()

@app.get("/")
async def root():
    logging.info("Handling request for root endpoint")
    return {"message": "Hello World"}


uvicorn.run(app, host="0.0.0.0", port=3000)

This was one of the weird behaviours I shared on slack a few weeks ago

[aabmass]

Thanks @emdneto it's a bug, but I'm not sure if this is the same issue as the OP without full repro.

What's happening here is another case of the timeout to BatchLogRecordProcessor.force_flush(timeout_millis) not being respected

opentelemetry-python/opentelemetry-sdk/src/opentelemetry/sdk/_shared_internal/__init__.py

Lines 213 to 214 in ff9dc82

	# TODO: Fix force flush so the timeout is used https://github.com/open-telemetry/opentelemetry-python/issues/4568.
	def force_flush(self, timeout_millis: Optional[int] = None) -> bool:

uvicorn.run() -> dictConfig() -> LoggingHandler.flush() -> BatchProcessor.force_flush() which runs forever because it's stuck in this loop.

#4636 improved the situation because we moved that call to a background thread, but the background thread still never ends and the process hangs after SIGINT.

(can try it on the main branch now, the server starts up fine but shutdown does hang)

# /// script
# requires-python = ">=3.13"
# dependencies = [
#     "fastapi",
#     "opentelemetry-api",
#     "opentelemetry-sdk",
#     "opentelemetry-distro",
#     "opentelemetry-instrumentation",
#     "opentelemetry-exporter-otlp",
#     "uvicorn",
#     "opentelemetry-instrumentation-fastapi",
#     "opentelemetry-instrumentation-asgi",
#     "opentelemetry-util-http",
#     "opentelemetry-semantic-conventions",
# ]
#
# [tool.uv.sources]
# opentelemetry-api = { git = "https://github.com/open-telemetry/opentelemetry-python", branch = "main", subdirectory = "opentelemetry-api" }
# opentelemetry-sdk = { git = "https://github.com/open-telemetry/opentelemetry-python", branch = "main", subdirectory = "opentelemetry-sdk" }
# opentelemetry-semantic-conventions = { git = "https://github.com/open-telemetry/opentelemetry-python", branch = "main", subdirectory = "opentelemetry-semantic-conventions" }
# opentelemetry-exporter-otlp = { git = "https://github.com/open-telemetry/opentelemetry-python", branch = "main", subdirectory = "exporter/opentelemetry-exporter-otlp" }
#
# opentelemetry-instrumentation-fastapi = { git = "https://github.com/open-telemetry/opentelemetry-python-contrib", branch = "main", subdirectory = "instrumentation/opentelemetry-instrumentation-fastapi" }
# opentelemetry-distro = { git = "https://github.com/open-telemetry/opentelemetry-python-contrib", branch = "main", subdirectory = "opentelemetry-distro" }
# opentelemetry-instrumentation = { git = "https://github.com/open-telemetry/opentelemetry-python-contrib", branch = "main", subdirectory = "opentelemetry-instrumentation" }
# opentelemetry-instrumentation-ask = { git = "https://github.com/open-telemetry/opentelemetry-python-contrib", branch = "main", subdirectory = "instrumentation/opentelemetry-instrumentation-asgi" }
# opentelemetry-util-http = { git = "https://github.com/open-telemetry/opentelemetry-python-contrib", branch = "main", subdirectory = "util/opentelemetry-util-http" }
# ///

import os
import logging

logging.basicConfig(level=0)
os.environ["OTEL_PYTHON_LOGGING_AUTO_INSTRUMENTATION_ENABLED"] = "true"

from opentelemetry.instrumentation import auto_instrumentation

auto_instrumentation.initialize()

import uvicorn

from fastapi import FastAPI

app = FastAPI()


@app.get("/")
async def root():
    logging.info("Handling request for root endpoint")
    return {"message": "Hello World"}


uvicorn.run(app, host="0.0.0.0", port=3000)

[DylanRussell]

I don't see the shutdown hanging behavior when I run this code. shutdown should kick force_flush out of that loop because of this condition

I do see the endless (not recursive) logging behavior though.. #4695 should fix that..

I am not sure how to run this code against main // local changes, because opentelemetry-instrument package installs old versions of the api/sdk.. Would appreciate pointer on how to do that

[ayuksekkaya]

Hello,

Is this issue the same as the one I am having at #4697 ?

Reading this issue and it sems like it's the same thing or related at least.

[DylanRussell]

Thanks @emdneto it's a bug, but I'm not sure if this is the same issue as the OP without full repro.

What's happening here is another case of the timeout to BatchLogRecordProcessor.force_flush(timeout_millis) not being respected

opentelemetry-python/opentelemetry-sdk/src/opentelemetry/sdk/_shared_internal/init.py

Lines 213 to 214 in ff9dc82

TODO: Fix force flush so the timeout is used #4568.

def force_flush(self, timeout_millis: Optional[int] = None) -> bool:
uvicorn.run() -> dictConfig() -> LoggingHandler.flush() -> BatchProcessor.force_flush() which runs forever because it's stuck in this loop.

#4636 improved the situation because we moved that call to a background thread, but the background thread still never ends and the process hangs after SIGINT.

(can try it on the main branch now, the server starts up fine but shutdown does hang)

I think this hanging may be a bug in uvicorn.. They have some logic to capture SIGINT and gracefully shutdown, although it also looks like they try to re-raise the signal afterwards: https://github.com/encode/uvicorn/blob/master/uvicorn/server.py#L314

But my guess is unicorn is capturing it, so our code never gets the signal.. If I press Ctrl C a second time the program does exit..