Fix bug where request body couldn't be logged after being used in logging middleware; Updated readme file to document current behaviour for request payload logging

Author: chrisK824

.gitignore

@@ -160,3 +160,5 @@ cython_debug/
 #  and can be added to the global gitignore or merged into this file.  For a more nuclear
 #  option (not recommended) you can uncomment the following to ignore the entire idea folder.
 #.idea/
+
+dev/

README.md

@@ -9,6 +9,10 @@ Groups logs coming from the same request lifecycle and propagates the maximum lo
 
 - **Request Logs Grouping**: Groups logs coming from the same request lifecycle to ease out log analysis using the Google Cloud Log Explorer. Grouping logger name can be customised and it defaults to the Google Cloud Project ID with '-request-logger' as a suffix.
 - **Request Maximum Log Level propagation**: Propagates the maximum log level throughout the request lifecycle to ease out log searching based on severity of an issue.
+- **Request Payload Logging** - More options to be exposed on that behaviour: 
+    - In case the request contains a payload, then this is logged into the parent log of request grouped logs
+    - For now content type of payload is assumed to be a valid JSON, otherwise it is discarded. More to be supported later on.
+    - The payload is logged as a dictionary using the `google-cloud-logging`'s method for `log_struct`. Since that method is logging only dictionaries, any JSON valid payload that is not a dictionary is wrapped into a dummy keyword to constuct one. The dummy keyword looks like that: `<original_type_of_payload>__payload_wrapper` The original or virtual dictionary is logged with `log_struct` along with the parent log of request grouped logs and ends up in field `jsonPayload`.
 
 ## API
 - Custom Cloud Logging Handler to use with official library `google-cloud-logging`: `FastAPIGAELoggingHandler`

fastapi_gae_logging/fastapi_gae_logging.py

@@ -3,6 +3,7 @@
 import contextvars
 import os
 import re
+import json
 from typing import Optional, Dict, Any
 from fastapi import FastAPI
 from starlette.exceptions import HTTPException
@@ -119,9 +120,14 @@ async def emit_request_log(self, request: Request, response: Response) -> None:
         if request.method in ('POST', 'PUT', 'PATCH', 'DELETE'):
             try:
                 payload = await request.json()
-            except Exception:
+            except json.JSONDecodeError:
                 pass
 
+        if not isinstance(payload, dict):
+            payload = {
+                f"{type(payload).__name__}_payload_wrapper": payload
+            }
+
         self.logger.log_struct(
             info=payload,
             resource=self.resource,
@@ -143,25 +149,38 @@ def __init__(self, app: ASGIApp, logger: GAERequestLogger):
 
     async def __call__(self, scope: Scope, receive: Receive, send: Send):
         if scope["type"] == "http":
-            request = Request(scope, receive=receive)
+
+            # https://stackoverflow.com/questions/64115628/get-starlette-request-body-in-the-middleware-context
+            # Mock function that returns a cached copy of the request
+            # so that anyone can ask for the body aftewards from the request object
+
+            receive_cached_ = await receive()
+
+            async def receive_cached():
+                return receive_cached_
+
+            request = Request(scope, receive=receive_cached)
 
             gae_request_context.set({
                 'trace': request.headers.get('X-Cloud-Trace-Context'),
                 'start_time': time.time(),
                 'max_log_level': logging.NOTSET
             })
 
+            # start with the default response in case of generic error
             response = Response(status_code=500)
 
-            async def send_wrapper(message: Dict[str, Any]) -> None:
+            # intercept the sent message to get the response status and body
+            # for later use
+            async def send_spoof_wrapper(message: Dict[str, Any]) -> None:
                 if message["type"] == "http.response.start":
                     response.status_code = message["status"]
                 elif message["type"] == "http.response.body":
                     response.body = message.get("body", b"")
                 await send(message)
 
             try:
-                await self.app(scope, receive, send_wrapper)
+                await self.app(scope, receive_cached, send_spoof_wrapper)
             except Exception as e:
                 if not isinstance(e, HTTPException):
                     logging.exception(e)

setup.py

@@ -2,7 +2,7 @@
 
 setup(
     name="fastapi-gae-logging",
-    version="0.0.1",
+    version="0.0.2",
     description="Custom Cloud Logging handler for FastAPI applications deployed in Google App Engine. \
     Groups logs coming from the same request lifecycle and propagates the maximum log level \
     throughout the request lifecycle using middleware and context management.",