Support metadata autodetection for Starlette

[thegoodlittlescript]

We're doing distributed tracing within a FastAPI app, which is based on Starlette. Currently this module only supports Flask and Django for things like httpRequest and Cloud Trace metadata.

As a feature request - can you add support for Starlette?

[thegoodlittlescript]

I've looked into the code where the get_request_data_from_flask and get_request_data_from_django methods read the trace headers ("X-Cloud-Trace-Context", and "Traceparent") from globally-available request objects. Thus the key appears to be getting a globally-available request object for Starlette.

This issue on Starlette discusses how to get such an object, incidentally for this same purpose of configuring a logger. Looks like what they settle on is a middleware approach using starlette-context.

Thus I imaging adding support might not be as seamless as flask/django. It may be "use this module, and add middleware", not just "use this module". I haven't had a chance to try this out but I'll report back when I do.

[arbrown]

Thanks for reaching out. Currently, we do not have plans to support additional frameworks for autodetection. However, if you are writing the logs yourself, you can manually populate httpRequest and trace fields yourself. We are working on providing samples for these use cases, but for now, please check out the recent blog post which announced metadata autodetection and shows an example of how to manually populate fields.

If FastApi is logging using generated code, then perhaps writing a custom middleware is your best option. I'll leave this issue open for now. Please do keep us posted on how this works out for you, and we can consider future support for such use cases.

[kkroening]

please check out the recent blog post which announced metadata autodetection and shows an example of how to manually populate fields.

That's a helpful article, but an issue with the recommended approach (if I'm not mistaken) is that it seems to require modifying all logger.info/logger.warning/etc. calls to explicitly include the request info, which is often not possible/practical when logging is spread out across an entire codebase (e.g. with dependencies that are not directly modifiable).

However, using a custom logging.Filter implementation instead seems to do the trick to ensure that the fields are populated automatically, just like the behavior around the built-in Flask + Django middleware:

class _StarletteGoogleCloudLoggingFilter(logging.Filter):
    """A :class:`logging.Filter` implementation that glues :mod:`google.cloud.logging`
    to :mod:`starlette` (or vice versa).

    This filter gets installed within the GCP logging middleware and is called just
    before :class:`google.cloud.logging.handlers.CloudLoggingFilter` to detect
    attributes such as the trace/span IDs.  It fills in such attributes on the log
    ``record`` object just before ``CloudLoggingFilter`` picks it up, and provides a
    mechanism to inject request info that's detected from Starlette's context.

    See also:
        * Starlette Context library:
          `starlette-context <https://github.com/tomwojcik/starlette-context>`_
        * Official google-cloud-logging GitHub issue related to Starlette integration:
          `python-logging googleapis/python-logging#505 <https://github.com/googleapis/python-logging/issues/505>`_
        * The downstream logic that picks up the logging record after this filter:
          :meth:`google.cloud.logging_v2.handlers.handlers.CloudLoggingHandler.filter`
        * Example Flask integration built into google-cloud-logging:
          :meth:`google.cloud.logging_v2.handlers._helpers.get_request_data_from_flask`
        * How to parse the ``X-Cloud-Trace-Context`` header:
          :meth:`google.cloud.logging_v2.handlers._parse_xcloud_trace`
    """

    def filter(self, record):
        # TODO: retrieve these values from Starlette using e.g. starlette-context.
        record.http_request = {
            'requestMethod': 'fixme',
            'requestUrl': 'fixme',
            'userAgent': 'fixme',
            'protocol': 'fixme',
        }
        project_id = 'fixme'
        trace_id = 'fixme'
        record.span_id = 'fixme'
        record.trace = f'projects/{project_id}/traces/{trace_id}'
        record.trace_sampled = False
        return True


def setup_logging():
    handler = google.cloud.logging.handlers.StructuredLogHandler()
    handler.filters.insert(0, _StarletteGoogleCloudLoggingFilter())
    google.cloud.logging_v2.handlers.setup_logging(handler)

...

async def homepage(request):
    logger.info('Look Ma, no extra json_fields!')
    return JSONResponse({'hello': 'world'})


app = Starlette(...)
setup_logging()

This takes advantage of some not-explicitly-documented-but-quite-useful functionality in CloudLoggingFilter: if the record's span_id, trace, etc. properties are defined ahead of time, then googe-cloud-logging picks it up, just like how it would if the properties were inferred using the built-in Flask/Django middleware.

The trick though is that the custom filter must be inserted before the CloudLoggingFilter by using handler.filters.insert(0, ...) so that the custom filter is executed first so that it has a chance to inject the record.* properties before handing the record off.

The end result is that once it's set up, logger.info('Hello world') can be called just like normal, and the request info is included automatically.

I haven't had a chance to wire up starlette-context as @thegoodlittlescript suggested, but at least there seems to be a way to plug it in now, assuming this approach passes sanity checks. Of course, maybe there are pitfalls here that I'm not aware of, so if there's a better way to go about it, I'm all ears.

(Actually, technically there's nothing Starlette-specific about the above example at this point, so the same approach could probably be used for other web frameworks besides Starlette)

[skion]

I took roughly the same approach as @kkroening for FastAPI and can confirm it works. If you're not planning to add support for additional frameworks, then it might make sense to document this approach better.

What might be a nice addition is to add a filters parameter to both StructuredLogHandler() and CloudLoggingHandler() which would first install those, so that you don't have to fiddle with filters.insert(0, ...) to ensure your filter is added first.

[skion]

Just realized that if you also happen to (or can) use OpenTelemetry's LoggingInstrumentor(), then you will already have most of the tracing metadata attached to the log records. This means you can simply copy over the fields from one to the other using the following filter, and inject it using @kkroening 's method above.

    class TraceFilter(logging.Filter):

        def __init__(self, project_id=None):
            self.project_id = project_id or "unknown"

        def filter(self, record):
            if trace_id := getattr(record, "otelTraceID"):
                record.trace = f"projects/{self.project_id}/traces/{trace_id}"
            record.span_id = getattr(record, "otelSpanID")
            return True

In fact, instead of supporting Web Framework X, could we instead add support for picking up these fields from OpenTelemetry if they exist? This feels more generic...