httpRequest processor

[petemounce]

We have a logging middleware that stamps each request with a canonical log-line. That attaches http request metadata as well as other things. That in turn causes GCP Logging to render those bits of metadata as lozenge-blobs in the UI, making them stand out a bit and also making the canonical log lines themselves stand out from the regular noise.

It was surprisingly fiddly to get this to work.

I'm not sure if you'd like to add some level of support? Here's something that resembles what I ended up doing:

class CanonicalLogLine(BaseHTTPMiddleware):
    def __init__(self, app: ASGIApp):
        super().__init__(app, dispatch=self.dispatch)
        self.logger = structlog.get_logger(__name__)

    async def dispatch(self, request: Request, call_next):
        start_time = time.perf_counter_ns()
        url = get_path_with_query_string(request.scope)
        client_host = request.client.host
        client_port = request.client.port
        http_method = request.method
        http_version = request.scope['http_version']
        response = await call_next(request)
        status_code = response.status_code
        request_duration = time.perf_counter_ns() - start_time
        self.logger.info(
            f"""{client_host}:{client_port} - "{http_method} {url} HTTP/{http_version}" {status_code}""",
            httpRequest={
                'latency': str(request_duration / 10**9) + 's',
                'protocol': f'HTTP/{http_version}',
                'remoteIp': f'{client_host}',
                'requestMethod': http_method,
                'requestUrl': str(request.url),
                'status': status_code,
                'userAgent': request.headers.get('user-agent', 'no-user-agent'),
            }
        )

        return response

... and then we have a structlog processor:

from structlog.types import EventDict, Processor, WrappedLogger


class AddGCPHTTP:
    def __init__(self, cloud_logging_key: str) -> None:
        self.cloud_logging_key = cloud_logging_key

    def setup(self) -> list[Processor]:
        return [self]

    def __call__(self, logger: WrappedLogger, method_name: str, event_dict: EventDict):
        if 'httpRequest' not in event_dict.keys():
            return event_dict

        event_dict[self.cloud_logging_key]['httpRequest'] = event_dict.pop('httpRequest')

        return event_dict

This was some time ago, and I don't remember the specifics but I do remember it being particularly papercutty. Perhaps if a field was not serialized how GCP expects (I vaguely recall things that are clearly numbers -- except status-code -- being necessary to pass as strings?) the whole thing didn't appear? Stuff like that.