Multiprocess worker calling handle_exit twice, though Ctrl-C is pressed only once.

[nodreb-borrus]

Sept 15 on #1160 (comment):

I am running uvicorn programatically with workers and getting this issue when I Ctrl-C the main process.

It only happens with workers, I think one of the worker processes is generating the exception since catching the asyncio exception on my uvicorn.run call does not stop the stack trace.

INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
INFO:     Started parent process [10954]
INFO:     Started server process [10958]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
INFO:     Started server process [10959]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
INFO:     Started server process [10961]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
INFO:     Started server process [10960]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
^CINFO:     Shutting down
INFO:     Shutting down
INFO:     Shutting down
INFO:     Shutting down
INFO:     Waiting for application shutdown.
INFO:     Application shutdown complete.
INFO:     Finished server process [10959]
INFO:     Waiting for application shutdown.
INFO:     Application shutdown complete.
INFO:     Finished server process [10961]
INFO:     Waiting for application shutdown.
INFO:     Application shutdown complete.
INFO:     Finished server process [10960]
INFO:     Finished server process [10958]
ERROR:    Traceback (most recent call last):
  File "/home/user/code/project/.venv/lib/python3.8/site-packages/starlette/routing.py", line 638, in lifespan
    await receive()
  File "/home/user/code/project/.venv/lib/python3.8/site-packages/uvicorn/lifespan/on.py", line 137, in receive
    return await self.receive_queue.get()
  File "/home/user/.asdf/installs/python/3.8.13/lib/python3.8/asyncio/queues.py", line 163, in get
    await getter
asyncio.exceptions.CancelledError

INFO:     Stopping parent process [10954]

A few other people have reported the same problem after me on that issue, but the issue is for a different problem and not applicable.

Dec 27:

I was looking at this issue again to see if I could track it down, and it comes down to handle_exit on Server:

uvicorn/uvicorn/server.py

Lines 305 to 310 in dd9d5d7

	def handle_exit(self, sig: int, frame: Optional[FrameType]) -> None:
	if self.should_exit and sig == signal.SIGINT:
	self.force_exit = True
	else:
	self.should_exit = True

Whenever handle_exit is called twice on one worker, force_exit is set which creates this stack trace. You can make it happen for all your workers by rapidly pressing Ctrl-C twice. I see the purpose of this behavior when the regular shutdown is blocked and you need to force your app to close.

The bug described in this issue is that handle_exit is being called twice on one worker randomly/sporadically, causing it to force_exit even though Ctrl-C is only pressed once.

I added some debug messages locally to show this, printing the process ID, and when it runs handle_exit/force_exit:

14253: handle_exit
14255: handle_exit
14254: handle_exit
14252: handle_exit
14252: handle_exit
14252: force_exit

This is with 4 workers, and again this only happens sometimes (roughly 1 in 5 in my case).

Since this issue is considered closed, I will figure out some hack for my app to remove this stack trace, but I wanted to share this info hoping it may lead to an eventual proper fix.

I believe it may be the same issue as #1662 but it has nothing to do with Docker.
This issue is adjacent to #1103 because there may be a solution somewhere in there, but that issue is addressing a much broader problem.

[nodreb-borrus]

I have continued debugging this, and I have figured out what causes this and why it happens inconsistently.

Continuing with an example using workers started with the multiprocess supervisor:

When you press Ctrl-C is sends SIGINT to the supervisor and to each of the worker processes.

When the supervisor receives SIGINT it begins its shutdown procedure, which calls terminate() on the worker processes, meaning it sends SIGTERM to the workers.

Usually, the workers receive SIGINT first and shutdown themselves, so the worker process terminates on its own before the supervisor asks it to.

Sometimes for whatever reasons of timing, the worker receives SIGTERM first, and then also receives SIGINT right after, handle_exit will be called twice.

Because of the logic of handle_exit which looks for SIGINT after should_exit has already been set by SIGTERM, it will set force_exit and create the stack trace error.

If a worker receives SIGINT and then SIGTERM, handle_exit will still be called twice, but the logic will not lead to force_exit.

Using my setup of 4 workers with debug messages printing the process id, and the signal being handled (2 - SIGINT, 15 - SIGTERM):

25662: handle_exit 2
25661: handle_exit 2
25659: handle_exit 2
25659: handle_exit 15
25660: handle_exit 2

Signal 2 comes before 15 for the process, this case terminates cleanly.

25702: handle_exit 2
25699: handle_exit 15
25699: handle_exit 2
25699: force_exit
25701: handle_exit 2
25700: handle_exit 2

Signal 15 comes before 2, this causes the force exit and stack trace.

Since the supervisor and workers are all on separate processes, this comes down to differences in execution timing between them.

I will think about how best to address this issue and propose a fix soon, in the meantime someone more familiar with this code may have a better opinion about it.