Send trace context with logs from web applications

[theacodes]

When running on App Engine (and potentially other platforms in the future), we should send along the trace context when writing logs. This context is available in the HTTP request headers as X-Cloud-Trace-Context and should be passed in the structured log as the traceId. For more details, read here.

Since this is a web request header, we will need to make the core of this web application-framework agnostic. We'll then need to write helpers/adaptors for Flask and Django.

To my knowledge, we have one blocking bug (#2997) that needs to be resolved before this can happen. Secondly, we need to agree on where the framework helpers should live. (@dhermes). I'm not aware of any other blockers.

Assigned to initially @waprin, as he currently has the most context and can hopefully address open questions and point out any additional pre-work that needs to be done. @liyanhui1228 and @duggelz are the product owners for this, and have offered to provide the implementation.

[theacodes]

Original context: #3355

[waprin]

#2673 is a blocker too because since we're no longer using fluentd we will need to specify the monitoredresource.

[theacodes]

Also blocked by: #3377

[theacodes]

@duggelz @liyanhui1228 #2673 is resolved, you should be good to start on #2997. Holler if you need anything.

[liyanhui1228]

OK sure.

[theacodes]

@liyanhui1228 #3410 is merged, so this work should now be unblocked. Holler if you need anything. :)

[liyanhui1228]

I have done this for flask and django. For flask the trace_id is just extracted from request headers, for django I used a middleware to store the request in thread local, and then get the trace_id from it. But the user will need to add the middleware to django settings before deploy the app. If this sounds reasonable, I can post a PR :) Any suggestions? @jonparrott @duggelz @waprin @dhermes

[tseaver]

AFAICT, this issue was closed with the merge of #3448.

[aatreya]

For flask (at least), this doesn't appear to be working as intended for us.

Specifically, the get_gae_labels() -> get_trace_id() -> get_trace_id_from_flask() code path is only called when the AppEngineHandler class is instantiated, which happens when get_default_handler() or setup_logging() is called when the app is initialized, not on every request. As a result, the trace_id is never populated during an actual request.

Calling setup_logging() on every Flask request is not an acceptable workaround since it adds overhead and results in a duplicate logger being added for every incoming request. Is this a bug, or are we using the library incorrectly?

[liyanhui1228]

@aatreya Thanks for the feedback! This log correlation feature was intended for AppEngine Flex specifically to match the behavior of AppEngine Standard. You can call handler.get_gae_labels() to get the trace_id in each request to update the labels field in the log payload. And then the logs will show up as correlated in the console.

[aatreya]

@liyanhui1228 My understanding is that the setup_logging() function is designed to automate all the environment-specific handler configuration, and that users of the library should never need to call handler.get_gae_labels() directly. Is this incorrect? If so, do you have any best practices on how this should be called from within a Flask request when the handler is automatically configured via setup_logging()?

For context, a previous version of the cloud logging code (https://github.com/GoogleCloudPlatform/python-compat-runtime/blob/master/appengine-vmruntime/vmruntime/cloud_logging.py) would automatically extract the trace_id from the environment without any explicit calls required during an actual request (since the trace_id collection happens during the processing of a specific log line rather than when the app is first loaded). Would it be possible to maintain this functionality?

[liyanhui1228]

@aatreya Yeah correct the setup_logging() configures the handler automatically. But unfortunately in GAE Flex the trace_id is neither stored in the environment variables nor in the log record as in the python compat runtime. So we have to extract it from the request headers. You can get the handler configured by setup_logging() via handler = client.get_default_handler() and then update the labels for a handler in each request.

[aatreya]

@liyanhui1228 It looks like client.get_default_handler() creates a new handler object on each call, rather than returning the handler that was already configured. This means that even if I were to manually call get_default_handler() on each request, the logging handler that is actually linked to the root logger wouldn't actually be affected. Am I mistaken?
Would it be possible to move get_gae_labels into the code path of the logging handler's emit() function so that the appropriate headers are obtained automatically on each request? This would mean the logging functionality would work as intended (just like in GAE Standard) out of the box, requiring only a simple call to setup_logging() at the start of the program.

[liyanhui1228]

@aatreya Instead of using client.setup_logging(), you can also add handler to a logger like below as described in the document:

import logging
import google.cloud.logging
from google.cloud.logging.handlers import AppEngineHandler

client = google.cloud.logging.Client()
handler = AppEngineHandler(client)
cloud_logger = logging.getLogger('cloudLogger')
cloud_logger.addHandler(handler)

@app.route('/')
def hello():
    handler.labels = handler.get_gae_labels()
    cloud_logger.error('test logging')
    return 'Hello'

Moving the get_gae_labels to emit() function can simplify the code, I have prepared a PR for changing that code path. But you can use the above code as the work around for now.

[aatreya]

Your PR fixed the issue for us. Thanks!