Suppress side-effects of signal propagation #2317

maxfischer2781 · 2024-04-26T17:41:22Z

Summary

This PR suppresses noise and dirt from signal propagation introduced in #1600.

Suppress tracebacks from worker/reload subprocesses on termination. These are triggered deep inside multiprocessing.process on any exception. Since the shutdown exception is expected, subprocesses spawned for workers/reload simply discard it.
- Fixes Unexcepted behavior while reloading #2294.
Always run cleanup of unix domain sockets when the uvicorn.run exits. This would previously be skipped on forced shutdown.

Note: I was not able to reproduce #2281 / #2289 so I do not know if they are fixed by this. However, this fixes the various reports on those discussions/issues about tracebacks.

~~I do not have access to a Windows machine for testing so had to emulate it. It would be nice if someone can confirm that this works on Windows.~~ A minimal repro is the program

# test.py
async def dummy_app(scope, receive, send): pass

run via

python -m uvicorn test:dummy_app --reload

@johanboekhoven kindly tested this on Windows.

Checklist

I understand that this PR may be closed in case there was no previous discussion. (This doesn't apply to typos!)
I've added a test for each change that was introduced, and I tried as much as possible to make a single atomic change.
- This change has no effect on behaviour, merely output.
I've updated the documentation accordingly.
- This change has no effect on documented behaviour.

Kludex · 2024-05-12T15:32:46Z

I can't reproduce it. How did you?

maxfischer2781 · 2024-05-13T07:03:39Z

@Kludex Sorry, I forgot to add one detail. To reproduce the Windows behaviour on UNIX, one must patch how the subprocesses are killed (SIGINT on Windows vs SIGTERM on UNIX).

In uvicorn/supervisors/basereload.py, one must change the use of terminate:

uvicorn/uvicorn/supervisors/basereload.py

Lines 92 to 93 in 0efd383

    
           else:  # pragma: py-win32 
        
               self.process.terminate()

to sending SIGINT explicitly:

        else:  # pragma: py-win32
            self.process._popen._send_signal(signal.SIGINT)

Afterwards, run the example mentioned above. Saving any file should trigger a reload and finishing the subprocess triggers a traceback as below:

...
INFO:     Application startup complete.
WARNING:  WatchFiles detected changes in 'uvicorn/supervisors/basereload.py'. Reloading...
INFO:     Shutting down
INFO:     Waiting for application shutdown.
INFO:     Application shutdown complete.
INFO:     Finished server process [55538]
err
Process SpawnProcess-3:
Traceback (most recent call last):
  File "/opt/homebrew/Cellar/[email protected]/3.12.2_1/Frameworks/Python.framework/Versions/3.12/lib/python3.12/asyncio/runners.py", line 118, in run
    return self._loop.run_until_complete(task)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "uvloop/loop.pyx", line 1517, in uvloop.loop.Loop.run_until_complete
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/homebrew/Cellar/[email protected]/3.12.2_1/Frameworks/Python.framework/Versions/3.12/lib/python3.12/multiprocessing/process.py", line 314, in _bootstrap
    self.run()
  File "/opt/homebrew/Cellar/[email protected]/3.12.2_1/Frameworks/Python.framework/Versions/3.12/lib/python3.12/multiprocessing/process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File "/Users/maxfischer/code_projects/uvicorn/uvicorn/_subprocess.py", line 79, in subprocess_started
    target(sockets=sockets)
  File "/Users/maxfischer/code_projects/uvicorn/uvicorn/server.py", line 66, in run
    return asyncio.run(self.serve(sockets=sockets))
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/homebrew/Cellar/[email protected]/3.12.2_1/Frameworks/Python.framework/Versions/3.12/lib/python3.12/asyncio/runners.py", line 194, in run
    return runner.run(main)
           ^^^^^^^^^^^^^^^^
  File "/opt/homebrew/Cellar/[email protected]/3.12.2_1/Frameworks/Python.framework/Versions/3.12/lib/python3.12/asyncio/runners.py", line 123, in run
    raise KeyboardInterrupt()
KeyboardInterrupt
INFO:     Started server process [55539]
INFO:     Waiting for application startup.
...

Note This patch is only for testing the Windows behaviour on UNIX and not part of the actual fix.

Kludex · 2024-05-15T15:18:08Z

uvicorn/main.py

+        if config.uds and os.path.exists(config.uds):
+            os.remove(config.uds)  # pragma: py-win32


Can we move this to Server.shutdown instead?

That seems sensible. I'll give it a try.

Thanks. Sorry for the delay on follow up.

I've experimented with this but see no way to make it work well. The socket can be owned by either main:run (for reload and workers) or Server (otherwise). When moving cleanup to Server.shutdown I would have to duplicate it inside the reload and worker code as well.

So main:run seems adequate for cleanup, since it owns the Server as well.

kenn · 2024-05-19T03:36:50Z

Not to distract your quality work, but I just wanted to add my experience.

I've had the following monkey patch in main.py to suppress tracebacks upon hitting ctrl+C on a dev machine (Mac), worked until 0.27.1:

if is_dev:
    get = asyncio.Queue.get

    async def new_get(self):
        try:
            return await get(self)
        except asyncio.exceptions.CancelledError:
            pass

    asyncio.Queue.get = new_get

But it stopped working after upgradeing to 0.29.0. If I'm not mistaken, this PR fixes this issue, correct?

INFO:     Shutting down
INFO:     Finished server process [98267]
ERROR:    Traceback (most recent call last):
  File ".pyenv/versions/3.10.10/lib/python3.10/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "uvloop/loop.pyx", line 1511, in uvloop.loop.Loop.run_until_complete
  File "uvloop/loop.pyx", line 1504, in uvloop.loop.Loop.run_until_complete
  File "uvloop/loop.pyx", line 1377, in uvloop.loop.Loop.run_forever
  File "uvloop/loop.pyx", line 555, in uvloop.loop.Loop._run
  File "uvloop/loop.pyx", line 474, in uvloop.loop.Loop._on_idle
  File "uvloop/cbhandles.pyx", line 83, in uvloop.loop.Handle._run
  File "uvloop/cbhandles.pyx", line 63, in uvloop.loop.Handle._run
  File ".venv/lib/python3.10/site-packages/uvicorn/server.py", line 68, in serve
    with self.capture_signals():
  File ".pyenv/versions/3.10.10/lib/python3.10/contextlib.py", line 142, in __exit__
    next(self.gen)
  File ".venv/lib/python3.10/site-packages/uvicorn/server.py", line 328, in capture_signals
    signal.raise_signal(captured_signal)
KeyboardInterrupt

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File ".venv/lib/python3.10/site-packages/starlette/routing.py", line 741, in lifespan
    await receive()
  File ".venv/lib/python3.10/site-packages/uvicorn/lifespan/on.py", line 137, in receive
    return await self.receive_queue.get()
  File ".pyenv/versions/3.10.10/lib/python3.10/asyncio/queues.py", line 159, in get
    await getter
asyncio.exceptions.CancelledError

Process SpawnProcess-1:
Traceback (most recent call last):
  File ".pyenv/versions/3.10.10/lib/python3.10/multiprocessing/process.py", line 314, in _bootstrap
    self.run()
  File ".pyenv/versions/3.10.10/lib/python3.10/multiprocessing/process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File ".venv/lib/python3.10/site-packages/uvicorn/_subprocess.py", line 78, in subprocess_started
    target(sockets=sockets)
  File ".venv/lib/python3.10/site-packages/uvicorn/server.py", line 65, in run
    return asyncio.run(self.serve(sockets=sockets))
  File ".pyenv/versions/3.10.10/lib/python3.10/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "uvloop/loop.pyx", line 1511, in uvloop.loop.Loop.run_until_complete
  File "uvloop/loop.pyx", line 1504, in uvloop.loop.Loop.run_until_complete
  File "uvloop/loop.pyx", line 1377, in uvloop.loop.Loop.run_forever
  File "uvloop/loop.pyx", line 555, in uvloop.loop.Loop._run
  File "uvloop/loop.pyx", line 474, in uvloop.loop.Loop._on_idle
  File "uvloop/cbhandles.pyx", line 83, in uvloop.loop.Handle._run
  File "uvloop/cbhandles.pyx", line 63, in uvloop.loop.Handle._run
  File ".venv/lib/python3.10/site-packages/uvicorn/server.py", line 68, in serve
    with self.capture_signals():
  File ".pyenv/versions/3.10.10/lib/python3.10/contextlib.py", line 142, in __exit__
    next(self.gen)
  File ".venv/lib/python3.10/site-packages/uvicorn/server.py", line 328, in capture_signals
    signal.raise_signal(captured_signal)
KeyboardInterrupt
INFO:     Stopping reloader process [98264]

maxfischer2781 · 2024-05-21T08:22:10Z

@kenn This PR will remove the Process SpawnProcess-1 part. Your patch should play nicely with this.

However, the first traceback does not seem to include your new_get function at all. In fact, the trace going through File ".venv/lib/python3.10/site-packages/uvicorn/lifespan/on.py", line 137, in receive and then immediately through File ".pyenv/versions/3.10.10/lib/python3.10/asyncio/queues.py", line 159, in get indicates new_get wasn't installed (it should show up in between otherwise). Perhaps you might want to double-check whether the code path that installs the patch is still run.

kenn · 2024-05-21T15:11:10Z

@kenn This PR will remove the Process SpawnProcess-1 part. Your patch should play nicely with this.

However, the first traceback does not seem to include your new_get function at all.

Thanks! new_get is used to overwrite the original get method with asyncio.Queue.get = new_get, hence monkey-patching. Save (as backup) the original get, use it in new_get, and then use new_get to overwrite the original get.

I know this is a dirty hack, but it works for a single purpose as expected — suppress the verbose tracebacks upon ctrl-C while preserving its original functionality 100%.

Kludex · 2024-05-24T04:20:37Z

Thanks @maxfischer2781 :)

This commit will update/upgrade Uvicorn [from 0.28.1 to 0.34.0](encode/uvicorn@0.28.1...0.34.0). There were some notable (but undocumented) updates to signal handling introduced in Uvicorn 0.29. The updates may result in child processes that do not shut down after the Uvicorn server gracefully shuts down ([encode/uvicorn#1600](encode/uvicorn#1600), [encode/uvicorn#2281](encode/uvicorn#2281), [encode/uvicorn#2289](encode/uvicorn#2289), [encode/uvicorn#2317](encode/uvicorn#2317)). For this reason, it may be helpful to check servers for orphaned child processes. See the GitHub references above for further info. As noted in commit 3ab51b6, Uvicorn workers were deprecated in 0.30.0. The workers are now available at `inboard.gunicorn_workers`. Other updates include an overhaul of the Uvicorn multiprocess manager (`uvicorn.supervisors.process.Multiprocess`, [encode/uvicorn#2183](encode/uvicorn#2183)) and small updates to the `forwarded_allow_ips`/`--forwarded-allow-ips` config setting.

This commit will update/upgrade Uvicorn [from 0.28.1 to 0.34.0](encode/uvicorn@0.28.1...0.34.0). There were some notable (but undocumented) updates to signal handling introduced in Uvicorn 0.29. The updates may result in child processes that do not shut down after the Uvicorn server gracefully shuts down ([encode/uvicorn#1600](encode/uvicorn#1600), [encode/uvicorn#2281](encode/uvicorn#2281), [encode/uvicorn#2289](encode/uvicorn#2289), [encode/uvicorn#2317](encode/uvicorn#2317)). For this reason, it may be helpful to check servers for orphaned child processes. See the GitHub references above for further info. As noted in commit 35d8d86, Uvicorn workers were deprecated in 0.30.0. The workers are now available at `inboard.gunicorn_workers`. Other updates include an overhaul of the Uvicorn multiprocess manager (`uvicorn.supervisors.process.Multiprocess`, [encode/uvicorn#2183](encode/uvicorn#2183)) and small updates to the `forwarded_allow_ips`/`--forwarded-allow-ips` config setting.

maxfischer2781 added 4 commits April 26, 2024 19:14

supress tracebacks on termination

088ac8a

always clean up unix sockets

545eca5

OS specific coverage

829c0dc

not covered on any OS

cf88d65

maxfischer2781 changed the title ~~Suppress side-effects of signal~~ Suppress side-effects of signal propagation Apr 27, 2024

maxfischer2781 mentioned this pull request Apr 27, 2024

Unexcepted behavior while reloading #2294

Closed

1 task

maxfischer2781 mentioned this pull request May 5, 2024

Remove forced raise_signal calls #2314

Closed

3 tasks

Merge branch 'master' into suppress-signal-traceback

e92bb27

Kludex reviewed May 15, 2024

View reviewed changes

Merge branch 'master' into suppress-signal-traceback

0f0b016

Kludex approved these changes May 24, 2024

View reviewed changes

Kludex merged commit 22873a9 into encode:master May 24, 2024
15 checks passed

This was referenced Jun 8, 2024

OSError: [Errno 24] Too many open files #1030

Open

[bug] Too many open files error signebedi/libreforms-fastapi#226

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Suppress side-effects of signal propagation #2317

Suppress side-effects of signal propagation #2317

maxfischer2781 commented Apr 26, 2024 •

edited

Loading

Kludex commented May 12, 2024

maxfischer2781 commented May 13, 2024 •

edited

Loading

Kludex May 15, 2024 •

edited

Loading

maxfischer2781 May 16, 2024

Kludex May 16, 2024

maxfischer2781 May 16, 2024

kenn commented May 19, 2024

maxfischer2781 commented May 21, 2024

kenn commented May 21, 2024

Kludex commented May 24, 2024

		if config.uds and os.path.exists(config.uds):
		os.remove(config.uds) # pragma: py-win32

Suppress side-effects of signal propagation #2317

Suppress side-effects of signal propagation #2317

Conversation

maxfischer2781 commented Apr 26, 2024 • edited Loading

Summary

Checklist

Kludex commented May 12, 2024

maxfischer2781 commented May 13, 2024 • edited Loading

Kludex May 15, 2024 • edited Loading

Choose a reason for hiding this comment

maxfischer2781 May 16, 2024

Choose a reason for hiding this comment

Kludex May 16, 2024

Choose a reason for hiding this comment

maxfischer2781 May 16, 2024

Choose a reason for hiding this comment

kenn commented May 19, 2024

maxfischer2781 commented May 21, 2024

kenn commented May 21, 2024

Kludex commented May 24, 2024

maxfischer2781 commented Apr 26, 2024 •

edited

Loading

maxfischer2781 commented May 13, 2024 •

edited

Loading

Kludex May 15, 2024 •

edited

Loading