Log statements are not grouped to parent request in App Engine Standard P3

[MeLight]

Environment details

• OS type and version: App Engine Python 3 Standard

Steps to reproduce

1. Add couple of logging statements
2. Go to Logs Explorer on your cloud console

Code example

import google.cloud.logging
import logging

client = google.cloud.logging.Client()

client.get_default_handler()
client.setup_logging()

logging.info("Testing lines")
logging.info("Again!")

Result:

As you can see every statement is on it's own line, as opposed to what's expected - the statements should be grouped under one log like in App Engine Standard Python2

How to group the statements to the parent request?

[snarfed]

I'm also seeing this, no matter what I try. Looks like it's the default with google-cloud-logging on App Engine Standard: the built in Python root logger sends to Cloud Logging, with resource type gae_app and log name projects/[PROJECT]/logs/app - good! - but those log lines aren't attached and rendered with the appengine.googleapis.com/request_log log entry.

I first noticed this change when I migrated to App Engine Python 3 a while back. I managed to fix it for google-cloud-logging 1.x with the code below, which I found here:

import google.cloud.logging
from google.cloud.logging.handlers import AppEngineHandler, setup_logging
logging_client = google.cloud.logging.Client()
setup_logging(AppEngineHandler(logging_client, name='stdout'))

... but this no longer works with google-cloud-logging 2.0. I've tried a bunch of variants, including no manual setup at all (ie relying on the default integration on App Engine), but no luck so far.

[daniel-sanche]

Thanks the the report. We're working on improving the cross-platform tests to make sure everything's consistent across GCP platforms, and this bug should be fixed by that effort. I'll try to bump of the priority of this one though, and see if I can fix it a bit earlier

What framework are you using for your web server to handle these requests?

[snarfed]

Thank you @daniel-sanche! Sounds good. I'll also try downgrading to 1.x in the meantime to see if that fixes it.

I'm on webapp2 (don't judge 😆), v3.0.0b1 for Python 3 support. My app is open source. Here's its current google-cloud-logging setup code.

[daniel-sanche]

@MeLight
I tried out a deployment on AppEngine standard today, and I was able to see grouping as normal (although I did see duplicate logs, and I saw the child logs both at the root, and under the request):

Here's the doumentation for how grouping works from the go library. The parent should be created automatically for you on AppEngine. Is the trace id being set properly in your logs? It should be set automatically using flask and django, but it may not be set if you're using a different web framework

[daniel-sanche]

@snarfed

Unfortunately I don't think we can fully support webapp2 going forward. They only officially support Python 2, and that's been dropped by GCP libraries going forward. I don't think we can justify maintaining tests/integrations for a library that doesn't officially support Python 3 yet.

What I will do though, is make sure you have a way to manually set the trace id on your logs. I'll work on that today

[MeLight]

@daniel-sanche thanks for the reply. I'm using Flask. I'm not sure it's set correctly. Where do I check/how do I set the trace?

[daniel-sanche]

If it's set properly, you should see a trace field as part of your Log Entry payload. Your payload structure should look something like mine from my image. It would be helpful if you could attach a screenshot of your current logs

Currently the trace is set automatically for the library, but I'm working on a feature to let users manually override the value

[MeLight]

@daniel-sanche nope, no trace.

[snarfed]

What I will do though, is make sure you have a way to manually set the trace id on your logs. I'll work on that today

Thanks again for looking at this! Any progress so far? Let me know if there's anything I can do to help.

[daniel-sanche]

nope, no trace.

Hmm, and you said you're using flask on App Engine Standard? And you ran client.setup_logging()? That should automatically add trace ids to your logs. If you can share some more code with me I can try to debug further.

The root of your issue is that the trace ids aren't being added. If we can solve that, you should start seeing the grouping work as expected

[daniel-sanche]

Thanks again for looking at this! Any progress so far? Let me know if there's anything I can do to help.

I opened two PRs around this (#120, #129), when they are merged, you will be able to add traces manually:

trace_header = webapp2.get_request().headers.get("X-CLOUD-TRACE-CONTEXT")
trace_id = trace_header.split("/", 1)[0]

logging.info('log test', extra={'trace':trace_id})

Unfortunately with the holidays coming up, we're going to be on a release freeze soon, so I likely won't be able to push the release until January

[snarfed]

Thanks @daniel-sanche! I tried this just now, using your sample code, but it didn't seem to work. Log browser (legacy) screenshot below, app log entry above, HTTP request below. I see the trace id in the HTTP request, and I emitted the trace id attached in extra in the the app log line, and they match, but I don't see it in the app log's fields. Should I?

Here's my setup_logging invocation:

    from google.cloud.logging.handlers import AppEngineHandler, setup_logging
    setup_logging(AppEngineHandler(logging_client, name='stdout'),
                  log_level=logging.DEBUG)

[snarfed]

(I installed your PR with git+https://github.com/snarfed/python-logging.git@manual_data#egg=manual_data in requirements.txt.)

[snarfed]

I've downgraded to 1.15.1 for now. We can figure out explicit trace id in the new year!

[snarfed]

Fwiw, I just noticed that this is also tracked (I guess?) in https://issuetracker.google.com/issues/118770775.

[snarfed]

Figured out my problem. I was still using AppEngineHandler, which seemed not to cooperate with the new extra kwarg. When I dropped that and switched to a plain vanilla logging client, it worked. Looking at AppEngineHandler.emit, if the trace id in extra ends up in record.trace, it seems like it should still be ok, but evidently not. 🤷

I'll also plug @oittaa's #149 (comment) for lifting X-Cloud-Trace-Context into the log record's trace id automatically, I'd obviously prefer that too!

[snarfed]

Here's the shim log handler class I added that extracts the trace header from webapp2:

class Webapp2TraceHandler(AppEngineHandler):
  """Log handler that adds trace id based on webapp2 request header.

  https://github.com/googleapis/python-logging/issues/110#issuecomment-745534629
  https://github.com/googleapis/python-logging/issues/149#issuecomment-782693201

  Also note that AppEngineHandler is evidently deprecated, so I may need to
  port that whole class into webutil eventually. :(
  https://github.com/googleapis/python-logging/issues/202
  """
  def emit(self, record):
    try:
      import webapp2
      trace = webapp2.get_request().headers.get('X-Cloud-Trace-Context')
      if trace:
        trace_id = trace.split('/', 1)[0]
        record.trace = f'projects/{APP_ID}/traces/{trace_id}'
    except (ImportError, AssertionError):
      pass

    return super().emit(record)