open-telemetry / opentelemetry-python

OpenTelemetry Python API and SDK
https://opentelemetry.io
Apache License 2.0
1.67k stars 570 forks source link

BatchLogRecordProcessor not working with multiprocessing #4005

Closed avramdjo closed 2 days ago

avramdjo commented 5 days ago

Describe your environment

OS: Ubuntu Python version: Python 3.11.9 SDK version: 1.25.0 API version: 1.25.0

What happened?

The BatchLogRecordProcessor exporter set up to a LoggerProvider set with set_logger_provider doesn't seem to export logs from within a forked or spawned subprocess using a PoolProcessExecutor.

Funnily enough, it does work with SimpleLogRecordProcessor, but it slows my application down significantly.

Steps to Reproduce

import logging
import logging.config

from azure.monitor.opentelemetry.exporter import AzureMonitorLogExporter
from opentelemetry._logs import set_logger_provider
from opentelemetry.sdk._logs import LoggerProvider
from opentelemetry.sdk._logs.export import BatchLogRecordProcessor

def setup():
    logger_provider = LoggerProvider()
    exporter = AzureMonitorLogExporter(connection_string="whatever")
    processor = BatchLogRecordProcessor(exporter=exporter)
    logger_provider.add_log_record_processor(processor)
    set_logger_provider(logger_provider)

setup()

logging.config.dictConfig(
    somedict
)  # includes my_predefined_logger with opentelemetry.sdk._logs.LoggingHandler handler and a console handler

def get_logger():
    return logging.getLogger("my_predefined_logger")

### in a different module

import multiprocessing as mp
from concurrent.futures import ProcessPoolExecutor

from mymodule import get_logger

logger = get_logger()

def my_function():
    logger.critical("Never exported, but shown in console because of my console")

logger.info("This log gets exported correctly")
with ProcessPoolExecutor(mp_context=mp.get_context("fork")) as executor:
    executor.submit(my_function)

Expected Result

both messages exported to azure application insights

Actual Result

only "This log gets exported correctly" is exported

Additional context

This is a uvicorn fastapi application running with 1 worker without async. All the logs get exported correctly, ones before uvicorn.run, the ones inside fastapi, except the ones in functions run from PoolProcessExecutor.

Please excuse the pseudo-code in the Steps to Reproduce section.

Would you like to implement a fix?

None

avramdjo commented 5 days ago

I've found 2 workarounds

  1. using logger_provider.force_flush() at the end of my forked function
  2. setting BatchLogRecordProcessor schedule_delay_millis to a very low value like 10 miliseconds, which so far works, but it sounds like a race condition waiting to happen.

I think this indicates that there isn't some fundamental lack of support for multiprocessing, or at least not an unsolvable one.

I obviously prefer the first solution, i just need to know if it's good. It also introduces some latency for every request. It seems to me like the problem is messages not being recorded in the batch accumulator, not necessarily that they're not being emitted to the exporter. I wish there was a functionality that safely "flushed" everything to the batch accumulator (before the fork exits, which happens in under a second) without pushing it through the exporter which is IO heavy.

I've ditched the SimpleLogRecordProcessor solution since it both introduces significant overhead + I've been seeing some Envelopes could not be exported and are not retryable errors.

I also could completely be missing the mark on this one, waiting for someone to reply.

avramdjo commented 2 days ago

The issue was the azure monitor exporter not being fork-safe.