Spans aren't exported when using multiprocessing with fork method

[alexmojaki]

With this code:

from multiprocessing import Process, set_start_method

import logfire

logfire.configure()


def worker():
    logfire.info('child')
    # logfire.force_flush()


if __name__ == '__main__':
    set_start_method('fork')
    with logfire.span('parent'):
        p = Process(target=worker)
        p.start()
        p.join()

the 'child' log appears in the console but not in the UI. It will appear in the UI if logfire.force_flush() is uncommented, or if fork is changed to spawn. If set_start_method isn't called then it depends on the OS. Side note, using fork also means that child will actually be a child span, as if context was propagated.

The issue here is that when using fork, atexit functions aren't called. This is supposedly fixed in 3.13 by python/cpython#114279 although I'm not seeing that on my machine.

[Kludex]

That's expected tho: https://opentelemetry-python.readthedocs.io/en/stable/examples/fork-process-model/README.html

[alexmojaki]

TBC, I'm not sure how much we can do about this. But:

1. That page talks about locks, it doesn't say anything about quietly dropping spans.
2. It talks about Gunicorn and uWSGI, it doesn't mention that the multiprocessing module will behave differently by default depending on the OS. Using post_fork doesn't seem relevant.
3. The exchange in spans sometimes never close #741 shows how confusing this is to debug.

[tvt173]

hey guys-- first and foremost, thanks again for helping debug this and for the great tool

I'll vouch for # 3... a logging tool plays a critical part in managing system reliability... the tool should feel reliable. it certainly does not though when your messages sometimes hit the server and sometimes do not... spans sometimes close, and sometimes they do not. some people can reproduce your issue and some cannot...

for a person like me, shopping around, trying to find the best tool for my company. it's a bad impression to leave and could have been a dealbreaker, if i hadn't gone through the effort to post the bug and gotten the quick turnaround to address my issue.

of course, ideally this bug would be fixed. but at a minimum, i would argue that you should at least document the known issue in your own documentation, or i would suspect you might have others in my shoes throw their hands up and walk away

sorry to be so critical, but i thought it might be helpful to to offer my honest opinion

[alexmojaki]

Thanks @tvt173 for the feedback. I want to just note that this is probably a problem for many other similar tools, and some of them probably don't even realise it. Registering cleanup using atexit is the norm and is expected to work. For example, when I try the same with Sentry:

from multiprocessing import Process, set_start_method

import sentry_sdk

sentry_sdk.init('https://...')


def worker():
    sentry_sdk.capture_message('worker message')
    raise Exception('worker exception')


if __name__ == '__main__':
    set_start_method('fork')
    p = Process(target=worker)
    p.start()
    p.join()
    raise Exception('main exception')

I indeed only see 'main exception'.

What happened in your original issue is that some of the data was sent early, particularly the pending spans created when the spans first started. This let you notice that there was a problem. It looks bad because of the unclosed spans. But OTEL itself doesn't have a concept of pending spans, it only sends completed spans. If you were using a different OTEL SDK, or just some other observability tool, it probably would have looked better, but you'd be less likely to notice that data was missing at all.

[alexmojaki]

Anyway, it's possible we can fix this at least partially by patching Process.__init__ and/or os._exit. But it needs investigation.

[tvt173]

thanks @alexmojaki . again, i simply want to advocate that at least a blurb should be added to the documentation, maybe around here, warning about this and suggesting the pattern you taught me to avoid it, since it is a thoroughly confusing and concerning bug from the user's point of view

[alexmojaki]

I'm currently working on patching os._exit. It seems to work well. Note to self to mention the fix on open-telemetry/opentelemetry-python#4215 which seems to be complaining about the same issue.

However, it does seem that fork is inherently unsafe in other ways which I don't understand. If you run this:

import warnings
from multiprocessing import Process, set_start_method
import logfire

logfire.configure()
warnings.simplefilter('always')
set_start_method('fork')
Process(target=lambda: None).start()

it says DeprecationWarning: This process (pid=6482) is multi-threaded, use of fork() may lead to deadlocks in the child.

This is documented in https://docs.python.org/3/library/os.html#os.fork. The only reason you haven't seen a warning already in your code is that DeprecationWarning doesn't show by default.

It's very unclear to me what the risks are at the moment of forking. There's discussion about this uncertainty in open-telemetry/opentelemetry-python#3307. I recommend calling set_start_method('spawn') if you can.

I'm wondering if we should try to raise a more visible warning when forking. I'm thinking no for now since we don't have concrete evidence yet of any actual issues once this one is patched. But the warning about deadlocks is a little scary.