Logs are messy when the server exits

[simonw]

The server exits cleanly with a 0 exit code, as designed - but it logs out a lot of ugly junk when it does that:

INFO:     Uvicorn running on http://127.0.0.1:8001 (Press CTRL+C to quit)
ERROR:    Exception in 'lifespan' protocol
Traceback (most recent call last):
  File "/Users/simon/.pyenv/versions/3.10.3/lib/python3.10/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/Users/simon/.pyenv/versions/3.10.3/lib/python3.10/asyncio/base_events.py", line 633, in run_until_complete
    self.run_forever()
  File "/Users/simon/.pyenv/versions/3.10.3/lib/python3.10/asyncio/base_events.py", line 600, in run_forever
    self._run_once()
  File "/Users/simon/.pyenv/versions/3.10.3/lib/python3.10/asyncio/base_events.py", line 1896, in _run_once
    handle._run()
  File "/Users/simon/.pyenv/versions/3.10.3/lib/python3.10/asyncio/events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
  File "/Users/simon/Dropbox/Development/datasette-scale-to-zero/datasette_scale_to_zero/__init__.py", line 46, in exit_if_no_recent_activity
    raise SystemExit(0)
SystemExit: 0

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/simon/.local/share/virtualenvs/datasette-scale-to-zero-dKxIqHhx/lib/python3.10/site-packages/uvicorn/lifespan/on.py", line 84, in main
    await app(scope, self.receive, self.send)
  File "/Users/simon/.local/share/virtualenvs/datasette-scale-to-zero-dKxIqHhx/lib/python3.10/site-packages/uvicorn/middleware/proxy_headers.py", line 75, in __call__
    return await self.app(scope, receive, send)
  File "/Users/simon/Dropbox/Development/datasette-scale-to-zero/datasette_scale_to_zero/__init__.py", line 27, in record_last_request
    await app(scope, receive, send)
  File "/Users/simon/.local/share/virtualenvs/datasette-scale-to-zero-dKxIqHhx/lib/python3.10/site-packages/datasette/utils/asgi.py", line 151, in __call__
    message = await receive()
  File "/Users/simon/.local/share/virtualenvs/datasette-scale-to-zero-dKxIqHhx/lib/python3.10/site-packages/uvicorn/lifespan/on.py", line 135, in receive
    return await self.receive_queue.get()
  File "/Users/simon/.pyenv/versions/3.10.3/lib/python3.10/asyncio/queues.py", line 159, in get
    await getter
asyncio.exceptions.CancelledError
Task exception was never retrieved
future: <Task finished name='Task-5' coro=<start_that_loop.<locals>.exit_if_no_recent_activity() done, defined at /Users/simon/Dropbox/Development/datasette-scale-to-zero/datasette_scale_to_zero/__init__.py:39> exception=SystemExit(0)>
Traceback (most recent call last):
  File "/Users/simon/.local/share/virtualenvs/datasette-scale-to-zero-dKxIqHhx/lib/python3.10/site-packages/click/core.py", line 1053, in main
    rv = self.invoke(ctx)
  File "/Users/simon/.local/share/virtualenvs/datasette-scale-to-zero-dKxIqHhx/lib/python3.10/site-packages/click/core.py", line 1659, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/Users/simon/.local/share/virtualenvs/datasette-scale-to-zero-dKxIqHhx/lib/python3.10/site-packages/click/core.py", line 1395, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/Users/simon/.local/share/virtualenvs/datasette-scale-to-zero-dKxIqHhx/lib/python3.10/site-packages/click/core.py", line 754, in invoke
    return __callback(*args, **kwargs)
  File "/Users/simon/.local/share/virtualenvs/datasette-scale-to-zero-dKxIqHhx/lib/python3.10/site-packages/datasette/cli.py", line 619, in serve
    uvicorn.run(ds.app(), **uvicorn_kwargs)
  File "/Users/simon/.local/share/virtualenvs/datasette-scale-to-zero-dKxIqHhx/lib/python3.10/site-packages/uvicorn/main.py", line 463, in run
    server.run()
  File "/Users/simon/.local/share/virtualenvs/datasette-scale-to-zero-dKxIqHhx/lib/python3.10/site-packages/uvicorn/server.py", line 60, in run
    return asyncio.run(self.serve(sockets=sockets))
  File "/Users/simon/.pyenv/versions/3.10.3/lib/python3.10/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/Users/simon/.pyenv/versions/3.10.3/lib/python3.10/asyncio/base_events.py", line 633, in run_until_complete
    self.run_forever()
  File "/Users/simon/.pyenv/versions/3.10.3/lib/python3.10/asyncio/base_events.py", line 600, in run_forever
    self._run_once()
  File "/Users/simon/.pyenv/versions/3.10.3/lib/python3.10/asyncio/base_events.py", line 1896, in _run_once
    handle._run()
  File "/Users/simon/.pyenv/versions/3.10.3/lib/python3.10/asyncio/events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
  File "/Users/simon/Dropbox/Development/datasette-scale-to-zero/datasette_scale_to_zero/__init__.py", line 46, in exit_if_no_recent_activity
    raise SystemExit(0)
SystemExit: 0

Would be nice if it didn't output that.

[simonw]

Slight improvement with this:

diff --git a/datasette_scale_to_zero/__init__.py b/datasette_scale_to_zero/__init__.py
index 723eee7..e0abbe5 100644
--- a/datasette_scale_to_zero/__init__.py
+++ b/datasette_scale_to_zero/__init__.py
@@ -43,7 +43,7 @@ def start_that_loop(datasette):
             if last_asgi is None:
                 continue
             if monotonic() - last_asgi > duration:
-                raise SystemExit(0)
+                loop.call_soon(sys.exit, 0)

     loop = asyncio.get_running_loop()
     loop.create_task(exit_if_no_recent_activity())

But it still outputs a bunch of stuff:

INFO:     Uvicorn running on http://127.0.0.1:8001 (Press CTRL+C to quit)
ERROR:    Exception in 'lifespan' protocol
Traceback (most recent call last):
  File "/Users/simon/.pyenv/versions/3.10.3/lib/python3.10/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/Users/simon/.pyenv/versions/3.10.3/lib/python3.10/asyncio/base_events.py", line 633, in run_until_complete
    self.run_forever()
  File "/Users/simon/.pyenv/versions/3.10.3/lib/python3.10/asyncio/base_events.py", line 600, in run_forever
    self._run_once()
  File "/Users/simon/.pyenv/versions/3.10.3/lib/python3.10/asyncio/base_events.py", line 1896, in _run_once
    handle._run()
  File "/Users/simon/.pyenv/versions/3.10.3/lib/python3.10/asyncio/events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
SystemExit: 0

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/simon/.local/share/virtualenvs/datasette-scale-to-zero-dKxIqHhx/lib/python3.10/site-packages/uvicorn/lifespan/on.py", line 84, in main
    await app(scope, self.receive, self.send)
  File "/Users/simon/.local/share/virtualenvs/datasette-scale-to-zero-dKxIqHhx/lib/python3.10/site-packages/uvicorn/middleware/proxy_headers.py", line 75, in __call__
    return await self.app(scope, receive, send)
  File "/Users/simon/Dropbox/Development/datasette-scale-to-zero/datasette_scale_to_zero/__init__.py", line 27, in record_last_request
    await app(scope, receive, send)
  File "/Users/simon/.local/share/virtualenvs/datasette-scale-to-zero-dKxIqHhx/lib/python3.10/site-packages/datasette/utils/asgi.py", line 151, in __call__
    message = await receive()
  File "/Users/simon/.local/share/virtualenvs/datasette-scale-to-zero-dKxIqHhx/lib/python3.10/site-packages/uvicorn/lifespan/on.py", line 135, in receive
    return await self.receive_queue.get()
  File "/Users/simon/.pyenv/versions/3.10.3/lib/python3.10/asyncio/queues.py", line 159, in get
    await getter
asyncio.exceptions.CancelledError

[simonw]

Asked on Twitter for some tips: https://twitter.com/simonw/status/1539673895296303104

Turns out this isn't a Python/asyncio thing, it's a Uvicorn thing: https://twitter.com/graingert/status/1539697480631197703

https://github.com/encode/uvicorn/blob/b22c9506b282e9c81591ed7f48781dc5759df0e0/uvicorn/lifespan/on.py#L87-L97

        except BaseException as exc:
            self.asgi = None
            self.error_occured = True
            if self.startup_failed or self.shutdown_failed:
                return
            if self.config.lifespan == "auto":
                msg = "ASGI 'lifespan' protocol appears unsupported."
                self.logger.info(msg)
            else:
                msg = "Exception in 'lifespan' protocol\n"
                self.logger.error(msg, exc_info=exc)

That logger is:

self.logger = logging.getLogger("uvicorn.error")

[simonw]

https://twitter.com/VictorStinner/status/1539730797795622912 says:

os._exit(0) avoids annoying errors at exit 😄

[simonw]

https://docs.python.org/3/library/os.html#os._exit

Exit the process with status n, without calling cleanup handlers, flushing stdio buffers, etc.

Note

The standard way to exit is sys.exit(n). _exit() should normally only be used in the child process after a fork().

[simonw]

I tried the os._exit(0) solution and it worked perfectly - the server terminates with a 0 exit code with no extra logging - but it makes me nervous!

[simonw]

I'm going to try shutting up that Uvicorn logger instead.