Access logger writing to closed file

[Jolloniego]

Hello and thanks in advance for any help with this 🙏

We have been running into the following issue in our production deployment (fastapi on GCP Cloud Run running uvicorn with default config from docker - 1vCPU 4GB RAM).

We have long running task of approx 10 sec (think of time.sleep instead of asyncio.sleep) that we run using as suggested here:

  loop = asyncio.get_running_loop()
  await loop.run_in_executor(
      thread_pool, process_message, params
  )

This is working fine and scaling to meet our demands, the problem is that we are running into thousands of the following error every day and we don't know how to address it:

--- Logging error ---
Traceback (most recent call last): File "/usr/local/lib/python3.9/logging/__init__.py", line 1086, in emit stream.write(msg + self.terminator) ValueError: I/O operation on closed file.

Call stack:
File "/usr/local/bin/uvicorn", line 8, in <module>
    sys.exit(main())
File "/usr/local/lib/python3.9/site-packages/click/core.py", line 1157, in __call__
    return self.main(*args, **kwargs)
File "/usr/local/lib/python3.9/site-packages/click/core.py", line 1078, in main
    rv = self.invoke(ctx)
File "/usr/local/lib/python3.9/site-packages/click/core.py", line 1434, in invoke
    return ctx.invoke(self.callback, **ctx.params)
File "/usr/local/lib/python3.9/site-packages/click/core.py", line 783, in invoke
    return __callback(*args, **kwargs)
File "/usr/local/lib/python3.9/site-packages/uvicorn/main.py", line 410, in main
    run(
File "/usr/local/lib/python3.9/site-packages/uvicorn/main.py", line 578, in run
    server.run()
File "/usr/local/lib/python3.9/site-packages/uvicorn/server.py", line 61, in run
    return asyncio.run(self.serve(sockets=sockets))
File "/usr/local/lib/python3.9/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
File "/usr/local/lib/python3.9/asyncio/base_events.py", line 634, in run_until_complete
    self.run_forever()
File "/usr/local/lib/python3.9/asyncio/base_events.py", line 601, in run_forever
    self._run_once()
File "/usr/local/lib/python3.9/asyncio/base_events.py", line 1905, in _run_once
    handle._run()
File "/usr/local/lib/python3.9/asyncio/events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
File "/usr/local/lib/python3.9/site-packages/uvicorn/protocols/http/h11_impl.py", line 428, in run_asgi
    result = await app( # type: ignore[func-returns-value]
File "/usr/local/lib/python3.9/site-packages/uvicorn/middleware/proxy_headers.py", line 78, in __call__
    return await self.app(scope, receive, send)
File "/usr/local/lib/python3.9/site-packages/fastapi/applications.py", line 289, in __call__
    await super().__call__(scope, receive, send)
File "/usr/local/lib/python3.9/site-packages/starlette/applications.py", line 122, in __call__
    await self.middleware_stack(scope, receive, send)
File "/usr/local/lib/python3.9/site-packages/starlette/middleware/errors.py", line 162, in __call__
    await self.app(scope, receive, _send)
File "/usr/local/lib/python3.9/site-packages/starlette/middleware/exceptions.py", line 68, in __call__
    await self.app(scope, receive, sender)
File "/usr/local/lib/python3.9/site-packages/fastapi/middleware/asyncexitstack.py", line 17, in __call__
    await self.app(scope, receive, send)
File "/usr/local/lib/python3.9/site-packages/starlette/routing.py", line 718, in __call__
    await route.handle(scope, receive, send)
File "/usr/local/lib/python3.9/site-packages/starlette/routing.py", line 276, in handle
    await self.app(scope, receive, send)
File "/usr/local/lib/python3.9/site-packages/starlette/routing.py", line 69, in app
    await response(scope, receive, send)
File "/usr/local/lib/python3.9/site-packages/starlette/responses.py", line 164, in __call__
    await send(
File "/usr/local/lib/python3.9/site-packages/starlette/middleware/exceptions.py", line 65, in sender
    await send(message)
File "/usr/local/lib/python3.9/site-packages/starlette/middleware/errors.py", line 159, in _send
    await send(message)
File "/usr/local/lib/python3.9/site-packages/uvicorn/protocols/http/h11_impl.py", line 498, in send
    self.access_logger.info(
    Message: '%s - "%s %s HTTP/%s" %d'
    Arguments: ('169.254.1.1:40261', 'POST

We run a monitoring /healthcheck endpoint every minute to count the number of active tasks, threads and FileDescriptors, something like:

    all_tasks = asyncio.all_tasks()
    num_tasks = len(all_tasks)
    num_threads = threading.active_count()
    num_file_descriptors = len(set(os.listdir("/proc/self/fd/")))

And we dont see the number of tasks go above 10, the number of threads over 20 or the FDs over 50.

Has anyone here seen an issue like this before? What are we missing?

[zShanCS]

I have been running into the same error with Uvicorn in Python.3.8_3.8.2800.0_x64.
Any updates?