Merge pull request #18046 from mvdbeek/access_logging_middleware

[24.0] Add middleware for logging start and end of request

.github/workflows/integration.yaml

@@ -62,7 +62,7 @@ jobs:
         id: minikube
         uses: CodingNagger/minikube-setup-action@v1.0.6
         with:
-          k8s-version: '1.19.16'
+          k8s-version: '1.23.0'
       - name: Launch Minikube
         run: eval ${{ steps.minikube.outputs.launcher }}
       - name: Check pods

.github/workflows/osx_startup.yaml

@@ -50,7 +50,7 @@ jobs:
           path: .tox
           key: tox-cache-${{ runner.os }}-${{ steps.full-python-version.outputs.version }}-${{ hashFiles('galaxy root/requirements.txt') }}-osx
       - name: Install miniconda  # use this job to test using Python from a conda environment
-        uses: conda-incubator/setup-miniconda@v2
+        uses: conda-incubator/setup-miniconda@v3
         with:
           activate-environment: ''
       - name: Restore client cache

doc/source/admin/galaxy_options.rst

@@ -3030,6 +3030,17 @@
 :Type: bool
 
 
+~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
+``use_access_logging_middleware``
+~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
+
+:Description:
+    Log request start as well as request end. Disables uvicorn access
+    log handler.
+:Default: ``false``
+:Type: bool
+
+
 ~~~~~~~~~~~~
 ``use_lint``
 ~~~~~~~~~~~~
@@ -5477,6 +5488,3 @@
     This requires the help_forum_api_url to be set.
 :Default: ``false``
 :Type: bool
-
-
-

lib/galaxy/config/sample/galaxy.yml.sample

@@ -1743,6 +1743,10 @@ galaxy:
   # job is complete.
   #debug: false
 
+  # Log request start as well as request end. Disables uvicorn access
+  # log handler.
+  #use_access_logging_middleware: false
+
   # Check for WSGI compliance.
   #use_lint: false
 

lib/galaxy/config/schemas/config_schema.yml

@@ -2193,6 +2193,13 @@ mapping:
           causes the files used by PBS/SGE (submission script, output, and error)
           to remain on disk after the job is complete.
 
+      use_access_logging_middleware:
+        type: bool
+        default: false
+        required: false
+        desc: |
+          Log request start as well as request end. Disables uvicorn access log handler.
+
       use_lint:
         type: bool
         default: false

lib/galaxy/webapps/base/api.py

@@ -1,6 +1,8 @@
 import os
 import stat
 import typing
+import uuid
+from logging import getLogger
 
 import anyio
 from fastapi import (
@@ -15,8 +17,12 @@ from starlette.responses import (
     FileResponse,
     Response,
 )
+from starlette_context import context
 from starlette_context.middleware import RawContextMiddleware
-from starlette_context.plugins import RequestIdPlugin
+from starlette_context.plugins import (
+    Plugin,
+    RequestIdPlugin,
+)
 
 from galaxy.exceptions import MessageException
 from galaxy.exceptions.utils import api_error_to_dict
@@ -32,6 +38,9 @@ if typing.TYPE_CHECKING:
     )
 
 
+log = getLogger(__name__)
+
+
 # Copied from https://github.com/tiangolo/fastapi/issues/1240#issuecomment-1055396884
 def _get_range_header(range_header: str, file_size: int) -> typing.Tuple[int, int]:
     def _invalid_range():
@@ -192,6 +201,31 @@ def add_exception_handler(app: FastAPI) -> None:
         return get_error_response_for_request(request, exc)
 
 
+class AccessLoggingMiddleware(Plugin):
+
+    key = "access_line"
+
+    async def process_request(self, request):
+        scope = request.scope
+        path = scope["root_path"] + scope["path"]
+        if scope["query_string"]:
+            path = f"{path}?{scope['query_string'].decode('ascii')}"
+        access_line = f"{scope['method']} {path} {uuid.uuid4()}"
+        log.debug(access_line)
+        return access_line
+
+    async def enrich_response(self, response) -> None:
+        access_line = context.get("access_line")
+        if status := response.get("status"):
+            log.debug(f"{access_line} {status}")
+
+
+def add_raw_context_middlewares(app: FastAPI):
+    getLogger("uvicorn.access").handlers = []
+    plugins = (RequestIdPlugin(force_new_uuid=True), AccessLoggingMiddleware())
+    app.add_middleware(RawContextMiddleware, plugins=plugins)
+
+
 def add_request_id_middleware(app: FastAPI):
     app.add_middleware(RawContextMiddleware, plugins=(RequestIdPlugin(force_new_uuid=True),))
 

lib/galaxy/webapps/galaxy/fast_app.py

@@ -16,6 +16,7 @@ from galaxy.schema.invocation import CustomJsonSchema
 from galaxy.version import VERSION
 from galaxy.webapps.base.api import (
     add_exception_handler,
+    add_raw_context_middlewares,
     add_request_id_middleware,
     GalaxyFileResponse,
     include_all_package_routers,
@@ -179,7 +180,10 @@ def initialize_fast_app(gx_wsgi_webapp, gx_app):
     app = get_fastapi_instance(root_path=root_path)
     add_exception_handler(app)
     add_galaxy_middleware(app, gx_app)
-    add_request_id_middleware(app)
+    if gx_app.config.use_access_logging_middleware:
+        add_raw_context_middlewares(app)
+    else:
+        add_request_id_middleware(app)
     include_all_package_routers(app, "galaxy.webapps.galaxy.api")
     include_legacy_openapi(app, gx_app)
     wsgi_handler = WSGIMiddleware(gx_wsgi_webapp)