4

I have an app in the Google App Engine Python 3 Standard Environment. I have it set up to group log entries by their request, as described in Writing Application Logs (in the "Viewing related request log entries" section).

That page notes:

The highest severity from the "child" log entries does not automatically apply to the top-level entry. If that behavior is desired, manually set the highest severity in the top-level entry.

The top-level entry in question is the request log that App Engine creates automatically. It's always at log level "Any". I'm not seeing how to change its log level/severity.

Here's (one branch of) the code I have now:

import os
from flask import request
from google.cloud import logging as gcp_logging
from google.cloud.logging.resource import Resource

client = gcp_logging.Client()
logger = client.logger('my_custom_log_type')
trace_id = (f"projects/{os.environ['GOOGLE_CLOUD_PROJECT']}/traces/"
            f"{request.headers['X-Cloud-Trace-Context'].split('/')[0]}")
res = Resource(type='gae_app',
               labels={'project_id': os.environ['GOOGLE_CLOUD_PROJECT'],
                       'module_id': os.environ['GAE_SERVICE'],
                       'version_id': os.environ['GAE_VERSION']})
logger.log_text('Sample log text', resource=res, trace=trace_id, severity='INFO')

It's working perfectly to group the logs with their requests, but the parent (request) log, e.g.,

> * 2019-11-19 15:54:56.613 EST  GET  200  1.21 KiB  390ms  Chrome 78  /

is displaying with the "Any" log level. I'd like it to be "Info" or "Error" as appropriate. How can I make this happen?

Steve McClellan
  • 116
  • 1
  • 1
  • 9
  • 1
    I don't think you can. That logged request is coming from Google and not from your application. The Google Frontend (GFE) sits in front of App Engine proxying request sent to your application. – John Hanley Nov 19 '19 at 22:55

1 Answers1

3

I've not found a way to tinker with the auto-generated log.

I'm still interested in hearing if there's a better way, so I'm not marking this answer as accepted.

But I have found a workaround that pretty much meets my needs, by adding my own request log and ignoring the automatically generated one.

For each child log, I use the same idea as in the question's code, but update a new attribute on flask's g object to keep track of the most severe log level so far within the request.

from flask import g

LOG_LEVELS = ('DEFAULT', 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL')

previous_level = g.get('log_level', 0)
g.log_level = max(previous_level, new_level)

(where new_level is the integer index of the level in LOG_LEVELS)

Then, to generate the new request log, I use a scaled-down version of this solution:

def log_request(response):
    logger = client.logger('my_request_logger')
    severity = LOG_LEVELS[g.get('log_level', 0)]
    request_info = {
        'requestMethod': request.method,
        'requestUrl': request.url,
        'status': response.status_code,
        'userAgent': request.headers.get('USER-AGENT'),
        'responseSize': response.content_length,
        'latency': g.request_duration(),
        'remoteIp': request.remote_addr
    }
    if request.method == 'POST':
        payload = request.get_json() or json.loads(request.data.decode())
    else:
        payload = {}
    logger.log_struct(payload,
                      trace=trace_id,
                      http_request=request_info,
                      severity=severity)

The above was in a my_logging module. Then, just a couple of additions to main.py to make this work:

import time
from flask import g
import my_logging

@app.before_request
def setup_timing():
    g.request_start_time = time.time()
    g.request_duration = lambda: f'{(time.time() - g.request_start_time):.5f}s'

@app.after_request
def log_request(response):
    my_logging.log_request(response)
    return response

This is working reasonably well - I'd love to hear any ideas to make it better.

Steve McClellan
  • 116
  • 1
  • 1
  • 9
  • Do you still get the other log entries nested under it with this approach? – Bogdan Dumitru Jan 10 '20 at 08:12
  • @BogdanDumitru If you use the combination of child logs (like in the code in the question) and parent logs (like in this answer), then all of the children will be nested under the parent, whenever the parent is visible. Note that if you don't want to also see the children separately, you need to make sure that Stackdriver's filters don't include the children's log type ('my_custom_log_type' in this case). – Steve McClellan Jan 10 '20 at 16:51
  • 1
    Yeah, I ended up implementing this approach myself and it's working better than the built-in approach so far, so thanks for this! It's also much easier to manage arbitrary labels associated with requests and then use those labels to filter requests in the UI. – Bogdan Dumitru Feb 18 '20 at 15:20
  • @SteveMcClellan I am trying to implement your solution. But without success so far. I asked a new question [here](https://stackoverflow.com/q/64818609/4878398). Could you have a look? – Erik van den Hoorn Nov 13 '20 at 09:42
  • @SteveMcClellan Hi, just wondering if you were able to find a better way to do this now? Is it possible to set the severity level for the auto-generated request log? – Kumar Mar 14 '21 at 07:55
  • 1
    @Kumar Alas, this is all I've got. The kludge above was good enough for the project I was working on, and I haven't worked with App Engine logging since. As far as I know, John Hanley's comment on the question is correct, and the auto-generated log can't be adjusted. – Steve McClellan Mar 14 '21 at 15:26