Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[bug] Too many open files error #226

Closed
janoskabedis opened this issue May 29, 2024 · 7 comments
Closed

[bug] Too many open files error #226

janoskabedis opened this issue May 29, 2024 · 7 comments

Comments

@janoskabedis
Copy link

References:

  1. https://askubuntu.com/questions/1182021/too-many-open-files
  2. https://stackoverflow.com/questions/6112703/what-is-a-file-handle-and-where-it-is-useful-for-a-programmer
2024-05-29 14:33:42,441 - uvicorn.error - ERROR - Exception in ASGI application
Traceback (most recent call last):
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/uvicorn/protocols/http/httptools_impl.py", line 411, in run_asgi
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/uvicorn/middleware/proxy_headers.py", line 69, in __call__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/fastapi/applications.py", line 1054, in __call__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/applications.py", line 123, in __call__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/middleware/errors.py", line 186, in __call__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/middleware/errors.py", line 164, in __call__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/middleware/authentication.py", line 49, in __call__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/middleware/exceptions.py", line 65, in __call__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/_exception_handler.py", line 64, in wrapped_app
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/_exception_handler.py", line 53, in wrapped_app
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/routing.py", line 756, in __call__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/routing.py", line 776, in app
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/routing.py", line 297, in handle
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/routing.py", line 77, in app
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/_exception_handler.py", line 64, in wrapped_app
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/_exception_handler.py", line 53, in wrapped_app
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/routing.py", line 72, in app
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/fastapi/routing.py", line 269, in app
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/fastapi/dependencies/utils.py", line 602, in solve_dependencies
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/concurrency.py", line 42, in run_in_threadpool
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/anyio/to_thread.py", line 56, in run_sync
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/anyio/_backends/_asyncio.py", line 2144, in run_sync_in_worker_thread
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/anyio/_backends/_asyncio.py", line 851, in run
  File "/opt/libreforms-fastapi/libreforms_fastapi/app/__init__.py", line 148, in get_config_depends
  File "/opt/libreforms-fastapi/libreforms_fastapi/utils/config.py", line 63, in get_config
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/dotenv/main.py", line 356, in load_dotenv
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/dotenv/main.py", line 92, in set_as_environment_variables
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/dotenv/main.py", line 76, in dict
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/dotenv/main.py", line 238, in resolve_variables
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/dotenv/main.py", line 83, in parse
  File "/usr/lib64/python3.11/contextlib.py", line 137, in __enter__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/dotenv/main.py", line 56, in _get_stream
OSError: [Errno 24] Too many open files: '/opt/libreforms-fastapi/instance/prod.env'
@signebedi signebedi mentioned this issue Jun 4, 2024
Open
@janoskabedis
Copy link
Author

This seems to be the offending logic:

libreforms-fastapi/libreforms_fastapi/app/__init__.py

Line 137 in cfab586

def get_config_context():

@signebedi signebedi mentioned this issue Jun 5, 2024
Open
@signebedi
Copy link
Owner

I genuinely do not know if this will resolve the issue. I added an lru_cache to get_config. I clear that cache when the app config is updated. I also clear that cache when we run the context managed get config.... What this means is that all API routes will pull cached data, I think, using the get_config_depends function, whereas the UI routes will pull direct from the file.

Still not perfect and very likely to be error prone. Will continue to monitor and make changes as needed. But, closing the issue for now.

signebedi added a commit that referenced this issue Jun 5, 2024
@signebedi
Added: dusting of config caching to reduce file handles (#226)
71d18cf
signebedi added a commit that referenced this issue Jun 5, 2024
@signebedi
Modified: changing around context managed config (#226)
982dbc0
@signebedi signebedi reopened this Jun 6, 2024
signebedi added a commit that referenced this issue Jun 7, 2024
@signebedi
Modified: caching strategy to use watchdog (#226)
c9e1c7d
@janoskabedis
Copy link
Author

Now, it's a different file:

2024-06-08 16:34:18,936 - uvicorn.error - ERROR - Exception in ASGI application
Traceback (most recent call last):
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/uvicorn/protocols/http/httptools_impl.py", line 411, in run_asgi
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/uvicorn/middleware/proxy_headers.py", line 69, in __call__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/fastapi/applications.py", line 1054, in __call__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/applications.py", line 123, in __call__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/middleware/errors.py", line 186, in __call__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/middleware/errors.py", line 164, in __call__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/middleware/authentication.py", line 49, in __call__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/middleware/exceptions.py", line 65, in __call__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/_exception_handler.py", line 64, in wrapped_app
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/_exception_handler.py", line 53, in wrapped_app
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/routing.py", line 756, in __call__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/routing.py", line 776, in app
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/routing.py", line 297, in handle
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/routing.py", line 77, in app
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/_exception_handler.py", line 64, in wrapped_app
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/_exception_handler.py", line 53, in wrapped_app
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/routing.py", line 72, in app
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/fastapi/routing.py", line 269, in app
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/fastapi/dependencies/utils.py", line 600, in solve_dependencies
  File "/opt/libreforms-fastapi/libreforms_fastapi/app/__init__.py", line 563, in get_doc_db
  File "/opt/libreforms-fastapi/libreforms_fastapi/utils/document_database.py", line 151, in get_document_database
  File "/opt/libreforms-fastapi/libreforms_fastapi/utils/document_database.py", line 328, in __init__
  File "/opt/libreforms-fastapi/libreforms_fastapi/utils/logging.py", line 14, in set_logger
  File "/usr/lib64/python3.11/logging/handlers.py", line 155, in __init__
  File "/usr/lib64/python3.11/logging/handlers.py", line 58, in __init__
  File "/usr/lib64/python3.11/logging/__init__.py", line 1181, in __init__
  File "/usr/lib64/python3.11/logging/__init__.py", line 1213, in _open
OSError: [Errno 24] Too many open files: '/opt/libreforms-fastapi/instance/log/production_tinydb.log'

@signebedi signebedi mentioned this issue Jun 8, 2024
Open
2 tasks
@signebedi
Copy link
Owner

signebedi commented Jun 8, 2024 •
edited
Loading

Potentially linked to:

  1. OSError: [Errno 24] Too many open files encode/uvicorn#1030
  2. Suppress side-effects of signal propagation encode/uvicorn#2317

If so, consider upgrading to the most recent version of uvicorn (0.30.1).

@janoskabedis
Copy link
Author

janoskabedis commented Jun 10, 2024 •
edited by signebedi
Loading

Even with caching, when we make a single change to the app config in production from the UI, it logs 21 (!) changes within a second of each other...

image

This has got to stem at least partially from the number of uvicorn workers (3) ... but still, it is inexplicable why there are so many file handles opened by this....

Notably, when we make a config change (admittedly, for a different config) from the Restful API, we get far fewer changes reported (consistently 12):

image

I will note that the UI-based config changes report more variable numbers of config reloading. This might be due to a mix of factors, including the javascript API calls made from the UI.

@signebedi
Copy link
Owner

Now, it's a different file:

2024-06-08 16:34:18,936 - uvicorn.error - ERROR - Exception in ASGI application
Traceback (most recent call last):
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/uvicorn/protocols/http/httptools_impl.py", line 411, in run_asgi
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/uvicorn/middleware/proxy_headers.py", line 69, in __call__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/fastapi/applications.py", line 1054, in __call__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/applications.py", line 123, in __call__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/middleware/errors.py", line 186, in __call__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/middleware/errors.py", line 164, in __call__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/middleware/authentication.py", line 49, in __call__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/middleware/exceptions.py", line 65, in __call__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/_exception_handler.py", line 64, in wrapped_app
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/_exception_handler.py", line 53, in wrapped_app
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/routing.py", line 756, in __call__
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/routing.py", line 776, in app
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/routing.py", line 297, in handle
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/routing.py", line 77, in app
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/_exception_handler.py", line 64, in wrapped_app
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/_exception_handler.py", line 53, in wrapped_app
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/starlette/routing.py", line 72, in app
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/fastapi/routing.py", line 269, in app
  File "/opt/libreforms-fastapi/venv/lib64/python3.11/site-packages/fastapi/dependencies/utils.py", line 600, in solve_dependencies
  File "/opt/libreforms-fastapi/libreforms_fastapi/app/__init__.py", line 563, in get_doc_db
  File "/opt/libreforms-fastapi/libreforms_fastapi/utils/document_database.py", line 151, in get_document_database
  File "/opt/libreforms-fastapi/libreforms_fastapi/utils/document_database.py", line 328, in __init__
  File "/opt/libreforms-fastapi/libreforms_fastapi/utils/logging.py", line 14, in set_logger
  File "/usr/lib64/python3.11/logging/handlers.py", line 155, in __init__
  File "/usr/lib64/python3.11/logging/handlers.py", line 58, in __init__
  File "/usr/lib64/python3.11/logging/__init__.py", line 1181, in __init__
  File "/usr/lib64/python3.11/logging/__init__.py", line 1213, in _open
OSError: [Errno 24] Too many open files: '/opt/libreforms-fastapi/instance/log/production_tinydb.log'

This may be tied to #221. In it, we made the document database a dependency injection for each route. The benefit is that we can now edit the app config at runtime (eg. through the UI) without needing to restart the app.

However, the issue is that a logger object is instantiated by the document database each time the document database connector is instantiated. That was written before the application moved to the document-database-as-dependency-injection setup.

So, if we are playing a game of whack-a-mole, we should modify the ManageDocumentDatabase class to expect a logger as a param, not to instantiate one.

signebedi added a commit that referenced this issue Jun 10, 2024
@signebedi
Added: improved logger options for document database (#226)
d39a56e
signebedi added a commit that referenced this issue Jun 11, 2024
@signebedi
Modified: doc db logging (#226)
0b8a718
signebedi added a commit that referenced this issue Jun 11, 2024
@signebedi
Removed: excess doc_db dependency injections (#226)
32113d2
This was referenced Jul 26, 2024
Closed
Open
@janoskabedis
Copy link
Author

[bug] Too many open files error rears again its ugly head
This issue has popped up again, in a production system with about a week of uptime and heavy use. See attached log snippet. The crazy thing here is that it is also files that are called within the jinja2 templates that are causing an issue.

production_uvicorn_snippet.log

I struggle to understand what a solution to this looks like. Perhaps: a nightly cron job to restart the server ... but this works against uptime/availability requirements in most production scenarios. Is there an architectural issue here that we have not been thinking through? Are there ways to cache more files and reduce the number of open file handles?

@janoskabedis janoskabedis mentioned this issue Nov 26, 2024
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@signebedi @janoskabedis