uwsgi + flask, got Respawned uWSGI worker, very frequently

[Liubey]

Describe your environment Describe any aspect of your environment relevant to the problem, including your Python version, platform, version numbers of installed dependencies, information about your cloud hosting provider, etc. If you're reporting a problem with a specific version of a library in this repo, please check whether the problem has been fixed on main.

Steps to reproduce
I use the code like:https://github.com/open-telemetry/opentelemetry-python/blob/main/docs/examples/fork-process-model/flask-uwsgi/app.py

What is the expected behavior?
report span rightly
What is the actual behavior?
logs like:

..The work of process 534 is done. Seeya!
Mon Jan 22 17:17:43 2024 - worker 4 (pid: 449) is taking too much time to die...NO MERCY !!!
worker 4 killed successfully (pid: 449)
Respawned uWSGI worker 4 (new pid: 568)

very very frequently. This can't be normal. But uwsgi provided no more logs.
and config like this:

master = true
enable-threads = True
harakiri-graceful-timeout = 5
threads = 2
processes = 4

Additional context
Add any other context about the problem here.

[Liubey]

update: threads = 1 will be ok. but threads = 2, THE Ninth Request will be hang till the worker Respawned.

[Liubey]

same code, When I use thrift.JaegerExporter(replace OTLPSpanExporter(endpoint="http://localhost:6831", insecure=True)), everything is ok.
It’s wired.

[lzchen]

@Liubey

What commands are you running to run the example? Is there a specific process runner you are using?

[Liubey]

@lzchen
uwsgi --http :8000 --wsgi-file app.py --callable application --master --enable-threads --threads 2 --processes 4
It’s wired cause replace OTLPSpanExporter to JaegerExporter is ok. I don't know why OTLPSpanExporter does't work fine at uwsgi mutithread.

[methane]

Try --lazy-apps

[Liubey]

It's not a easy way to change base config for a mature business project😂

[methane]

Is it harder than making whole otel-python[-contrib] fork-safe?

[Liubey]

😭you are right. I will try to research and drive it.

[methane]

FYI, ddtrace-py also require lazy-apps.

https://github.com/DataDog/dd-trace-py/blob/8b11b36d29ee4cda1a6000d10fd74208bbb5f39d/ddtrace/internal/uwsgi.py#L35

[Liubey]

@methane Oh, thanks for your addition information.
But strange thing is, I have two project, One use django + uwsgi + OTLPSpanExporter, it's ok and not set lazy-apps.

[methane]

lazy-apps is the most straightforward.
But there are some options to avoid the fork after loading app.

[methane]

@Liubey Do you read and follow this?

https://github.com/open-telemetry/opentelemetry-python/tree/main/docs/examples/fork-process-model#working-with-fork-process-models

[Liubey]

@methane Yes, I saw that before. In my uwsgi + flask project, I use @postfork to test, It still not work, like I sad:"got Respawned uWSGI worker, very frequently"

[methane]

I use the code like:https://github.com/open-telemetry/opentelemetry-python/blob/main/docs/examples/fork-process-model/flask-uwsgi/app.py

like? Did you reproduce it with exact the code?

Unless there is a reproducible step, all efforts to investigate will be in vain.

[Liubey]

@methane yes, When I use

I got same thing when I wait a few minutes after server startup for receive requests.
the highlight is max-requests and thread set.

[Liubey]

maybe the key setter is '''max-requests''', When I remove it, It looks normal.

[Liubey]

When I set '''max-requests=50''' AND '''processes=4''', the 201~204 request will hang for 50 seconds+

and got "Respawned uWSGI worker " for the 4 processor

[Liubey]

@jpkrohling @methane @lzchen Could you have any ideas for that? Sorry for disturb your.

[Liubey]

the command is :
uwsgi --http :8000 --wsgi-file app.py --callable application --master --enable-threads --threads 2 --processes 4 --max-requests 50

[methane]

OK. I got it.

• BatchSpanProcessor uses daemon thread. So BatchSpanProcessor.shutdown() is needed to stop it.

opentelemetry-python/opentelemetry-sdk/src/opentelemetry/sdk/trace/export/__init__.py

Line 189 in 8ad10f7

self.worker_thread = threading.Thread(

• TracerProvider uses atexit to call shutdown(). And its shutdown calls BatchSpanProcessor.shutdown().

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

Lines 1181 to 1182 in 8ad10f7

	if shutdown_on_exit:
	self._atexit_handler = atexit.register(self.shutdown)

• But uwsgi may not invoke atexit. So deamon thread is not stopped and Python process keep running.

unbit/uwsgi#2063

[Liubey]

@methane Thank you very much for your careful analysis. This is unbelievable.
Is there an easy solution to bypass the bug, patch the OtelBatchSpanProcessor thread to deamon=False?

[Liubey]

@methane Oh,sorry to mention, When I use JaegerExporter, I also use BatchSpanProcessor, so I think the key thing is OTLPExporter.shutdown or export?

[Liubey]

test with http.OTLPSpanExporter, looks normal, not hanging, just

[methane]

I can reproduce it with http.OTLPSpanExporter.
I don't test JaegerExporter yet.

grpc exporter shutdown is not related because it doesn't use daemon thread.

[Liubey]

@methane
maybe the key thing is grpc, cause I use thrift.JaegerExporter, it's ok. and grpc.JaegerExporter is not ok.

I found some message on grpc rep, see-->grpc/grpc#23796 (comment)
He said :
numbsafari commented on Feb 2, 2022
Hi, 2022 checking in. It appears that gRPC doesn’t work with any kind of pre-fork (eg uWSGI) model system unless you specify the environment variables noted above.

Perhaps a solution would be to add some documentation?

[methane]

It is separeted issue. It is fork-safe problem. And --lazy-apps (recommended) or @post_fork can avoid it.

[methane]

I made a pull request to uwsgi that fixes no atexit call issue when mixing threads and max-requests.

[Liubey]

@methane Thank you so much. Hope uwsgi could merge the request quickly.😂

[methane]

UPDATE: This is not caused by BatchSpanProcessor. Python doesn't wait daemon threads at all. I'm sorry about it.

This is caused by uwsgi. uwsgi uses pthread_cancel() to stop worker even for graceful shutdown. It is really bad idea. pthread_cancel() is almost impossible to use safely. I think both of uwsgi and Python are cancel-safe.

For the record, I can reproduce it easily even I remove all opentelemetry imports.

[Liubey]

@methane Thank you for your comment.
But what I want to know is that if the thread is set to 1, it doesn't seem to happen this case, even max-requests set.

for example:

 uwsgi --http :8000 --wsgi-file app.py --callable application --master --enable-threads --threads 1 --processes 4 --max-requests 50

stop the worker very fast.

[methane]

When threads=1, there is only main thread. When main thread reached max-requests, main thread tries to stop other thread, but no other thread. pthread_cancel() is not called so no problem.

I guess the hungup is happens when worker thread excpet main thread (core_id=0) reaches max-requests and calls pthread_cancel() to main thread. But I am not sure. Threads is hard. But pthread_cancel() is too hard. Sometime, I can not even attaching broken process.

For fixing it, please try unbit/uwsgi#2615 and unbit/uwsgi#2619.

Anyway, I can reproduce it without any opentelemetry imports. So this is not an issue of otel.
I think this issue should be closed.

[Liubey]

Thank you for your additional information. I will close this issue. Once again, I appreciate your help for this issue, and I wish you thread-safety forever. Haha😝