From 6023e24d424d41d3ea5f4d88f82b44f56695a1fb Mon Sep 17 00:00:00 2001 From: Elijah DeLee Date: Wed, 21 Aug 2024 13:36:30 -0400 Subject: [PATCH] Add middleware that apps can use to handle graceful timeout signal uwsgi 2.0.22+ offers option to send a user-defined signal at for a "graceful" timeout before the real harakiri occurs. gunicorn sends SIGABRT (signal 6) as graceful timeout signal before sending SIGKILL Apps can use this middleware to log a traceback indicating what code was executing when the graceful timeout signal was received. --- .../lib/middleware/logging/__init__.py | 4 +-- .../lib/middleware/logging/log_request.py | 25 +++++++++++++++++++ docs/logging.md | 17 +++++++++++++ test_app/settings.py | 1 + .../middleware/test_traceback_logger.py | 19 ++++++++++++++ test_app/urls.py | 1 + test_app/uwsgi.ini | 7 ++++-- test_app/views.py | 15 ++++++++--- 8 files changed, 81 insertions(+), 8 deletions(-) create mode 100644 test_app/tests/lib/logging/middleware/test_traceback_logger.py diff --git a/ansible_base/lib/middleware/logging/__init__.py b/ansible_base/lib/middleware/logging/__init__.py index b5c704f1c..5c5d8fa58 100644 --- a/ansible_base/lib/middleware/logging/__init__.py +++ b/ansible_base/lib/middleware/logging/__init__.py @@ -1,3 +1,3 @@ -from ansible_base.lib.middleware.logging.log_request import LogRequestMiddleware +from ansible_base.lib.middleware.logging.log_request import LogRequestMiddleware, LogTracebackMiddleware -__all__ = ('LogRequestMiddleware',) +__all__ = ('LogRequestMiddleware', 'LogTracebackMiddleware') diff --git a/ansible_base/lib/middleware/logging/log_request.py b/ansible_base/lib/middleware/logging/log_request.py index 6daed0ed3..8e11e7c2f 100644 --- a/ansible_base/lib/middleware/logging/log_request.py +++ b/ansible_base/lib/middleware/logging/log_request.py @@ -1,10 +1,35 @@ import logging +import signal +import traceback +import uuid from ansible_base.lib.logging import thread_local logger = logging.getLogger(__name__) +class LogTracebackMiddleware: + transactions = {} + + @classmethod + def handle_signal(cls, *args): + for t_id, request in LogTracebackMiddleware.transactions.items(): + logger.error(f"Received graceful timeout signal for {request.method} path: {request.path} while in stack: {''.join(traceback.format_stack())}") + + def __init__(self, get_response): + self.get_response = get_response + signal.signal(signal.SIGSYS, LogTracebackMiddleware.handle_signal) + signal.signal(signal.SIGABRT, LogTracebackMiddleware.handle_signal) + + def __call__(self, request): + t_id = str(uuid.uuid4()) + LogTracebackMiddleware.transactions[t_id] = request + try: + return self.get_response(request) + finally: + LogTracebackMiddleware.transactions.pop(t_id) + + class LogRequestMiddleware: """ Inject the request into the thread local so that it can be accessed by the logging filter. diff --git a/docs/logging.md b/docs/logging.md index 76dbdd4e0..4f70ddd65 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -52,3 +52,20 @@ LOGGING = { ``` After that, the request ID should automatically show up in logs, when the header is passed in. + +## Logging Stack on Timeout + +django-ansible-base provides machinery to print the stack trace when a request times out. +To do this, you will need to: + +1. Set uwsgi params similar to that in `test_app/uwsgi.ini`. +2. Add `ansible_base.lib.middleware.logging.LogTracebackMiddleware` to `MIDDLEWARE` setting + +You can try to test this with test_app by running the docker compose server (so it runs with uwsgi), +and then visiting http://localhost:8000/api/v1/timeout_view/ and viewing the logs. +Within those logs, you should be able to see the culprit: + +``` +test_app-1 | File "/src/test_app/views.py", line 185, in timeout_view +test_app-1 | time.sleep(60*10) # 10 minutes +``` diff --git a/test_app/settings.py b/test_app/settings.py index 89c3052d3..eb6b980de 100644 --- a/test_app/settings.py +++ b/test_app/settings.py @@ -86,6 +86,7 @@ 'django.middleware.clickjacking.XFrameOptionsMiddleware', 'crum.CurrentRequestUserMiddleware', 'ansible_base.lib.middleware.logging.LogRequestMiddleware', + 'ansible_base.lib.middleware.logging.LogTracebackMiddleware', ] REST_FRAMEWORK = { diff --git a/test_app/tests/lib/logging/middleware/test_traceback_logger.py b/test_app/tests/lib/logging/middleware/test_traceback_logger.py new file mode 100644 index 000000000..fff94fc34 --- /dev/null +++ b/test_app/tests/lib/logging/middleware/test_traceback_logger.py @@ -0,0 +1,19 @@ +from unittest import TestCase, mock + +from django.http import HttpRequest + +from ansible_base.lib.middleware.logging.log_request import LogTracebackMiddleware + + +class TestLogTracebackMiddleware(TestCase): + def test_log_traceback_middleware(self): + get_response = mock.MagicMock() + request = HttpRequest() + request.method = "GET" + request.path = "/test" + + middleware = LogTracebackMiddleware(get_response) + response = middleware(request) + + # ensure get_response has been returned + self.assertEqual(get_response.return_value, response) diff --git a/test_app/urls.py b/test_app/urls.py index 3a49a87fb..e45530a7b 100644 --- a/test_app/urls.py +++ b/test_app/urls.py @@ -19,6 +19,7 @@ re_path(r"^admin/", admin.site.urls, name="admin"), path('api/v1/', include(resource_api_urls)), path('api/v1/', views.api_root), + path('api/v1/timeout_view/', views.timeout_view, name='test-timeout-view'), path('login/', include('rest_framework.urls')), path("__debug__/", include("debug_toolbar.urls")), ] diff --git a/test_app/uwsgi.ini b/test_app/uwsgi.ini index 09d3528db..df1c307ed 100644 --- a/test_app/uwsgi.ini +++ b/test_app/uwsgi.ini @@ -8,12 +8,15 @@ vacuum = true # Log to stdout logto = /dev/stdout +log-master = true #disable-logging = true # Increase buffer size buffer-size = 32768 -# Other recommended settings +# Give signal 31 (SIGSYS) to work with LogTracebackMiddleware http-timeout = 60 harakiri = 60 - +harakiri-graceful-timeout = 50 +harakiri-graceful-signal = 31 +py-call-osafterfork = true diff --git a/test_app/views.py b/test_app/views.py index 978a2dc0f..513242aa9 100644 --- a/test_app/views.py +++ b/test_app/views.py @@ -1,4 +1,5 @@ import logging +import time from itertools import chain from django.shortcuts import render @@ -160,7 +161,7 @@ def api_root(request, format=None): # want '^users/$' [name='user-list'] # do not want '^users/(?P[^/.]+)/organizations/$' [name='user-organizations-list'], if '-list' in url.name and url.pattern._regex.count('/') == 1: - list_endpoints[url.name.removesuffix('-list')] = get_relative_url(url.name, request=request, format=format) + list_endpoints[url.name.removesuffix('-list')] = get_relative_url(url.name) from ansible_base.api_documentation.urls import api_version_urls as docs_urls from ansible_base.authentication.urls import api_version_urls as authentication_urls @@ -168,16 +169,22 @@ def api_root(request, format=None): for url in docs_urls + authentication_urls[1:]: if isinstance(url, URLPattern): try: - list_endpoints[url.name] = get_relative_url(url.name, request=request, format=format) + list_endpoints[url.name] = get_relative_url(url.name) except NoReverseMatch: pass - list_endpoints['service-index'] = get_relative_url('service-index-root', request=request, format=format) - list_endpoints['role-metadata'] = get_relative_url('role-metadata', request=request, format=format) + list_endpoints['service-index'] = get_relative_url('service-index-root') + list_endpoints['role-metadata'] = get_relative_url('role-metadata') + list_endpoints['timeout-view'] = get_relative_url('test-timeout-view') return Response(list_endpoints) +@api_view(['GET']) +def timeout_view(request, format=None): + time.sleep(60 * 10) # 10 minutes + + class MultipleFieldsViewSet(TestAppViewSet): serializer_class = serializers.MultipleFieldsModelSerializer