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.

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')

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.

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
+```

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 = {

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)

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")),
 ]

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

test_app/views.py

@@ -1,4 +1,5 @@
 import logging
+import time
 from itertools import chain
 
 from django.shortcuts import render
@@ -160,24 +161,30 @@ def api_root(request, format=None):
         # want '^users/$' [name='user-list']
         # do not want '^users/(?P<pk>[^/.]+)/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
 
     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