Logging: support sending structured logs to stackdriver via stdlib 'logging'.

[yuvipanda]

google-cloud-logging version: 1.8.0

I want to send structured logs to stackdriver from Python using the standard logging module. You can integrate structured logging to the Python logging module with either https://github.com/madzak/python-json-logger or http://www.structlog.org/en/stable/. Would be great to preserve those structures as part of jsonPayload when sent to stackdriver. Currently, these get stringified and sent as jsonPayload.message instead.

[parthmishra]

What is the status of this request? I know the root issue is that the formatter must know the attributes of the extra arguments passed into the stdlib logger, but is it too much of hassle to the point of being won't fix? My hesitation with the log_struct() method is the synchronous nature of it, perhaps an asynchronous transport mechanism for it could be a useful workaround?

[tseaver]

@parthmishra The request as it stands (extract the "extra" fields from stdlib's LogRecord and convert them to log_struct) is unlikely to be implemented in this library. This comment on issue googleapis/google-cloud-python#6488 suggests one possibility for working around it.

To deal just with the synchronous bit, you could interact directly with the "background thread handler" transport. Its main worker method just polls the queue for lists of dicts to be pushed to the API: https://github.com/googleapis/google-cloud-python/blob/a14ffbaa50f7823c2792e91413a37cbc3ce687f5/logging/google/cloud/logging/handlers/transports/background_thread.py#L134-L152

[crazystick]

I wanted to do something similar in order to have errors show up in Stackdriver Error Reporting, which is possible according to this issue I opened. I ended up doing it like this, but I think it would be neater if you could subclass _Worker and inject it into CloudLoggingHandler alongside the transport. Anyway, this works:

from google.cloud.logging.handlers.transports.background_thread import BackgroundThreadTransport, _Worker

def my_enqueue(
        self, record, message, resource=None, labels=None, trace=None, span_id=None):
    entry = {
        "info": {
            "message": message, "python_logger": record.name
        },
        "severity": record.levelname,
        "resource": resource,
        "labels": labels,
        "trace": trace,
        "span_id": span_id,
        "timestamp": datetime.utcfromtimestamp(record.created),
    }

    if record.levelno >= logging.WARNING:
        entry["info"]["context"] = {"reportLocation": {"filePath": record.filename, 
                                        "lineNumber": record.lineno,
                                        "functionName": record.funcName}}
        entry["info"]["serviceContext"] = {"service": "my_service", "version": "1"}
        entry["info"]["@type"] = "type.googleapis.com/google.devtools.clouderrorreporting.v1beta1.ReportedErrorEvent"

    self._queue.put_nowait(entry)

# monkeypatch enqueue function
_Worker.enqueue = my_enqueue

cloud_handler = CloudLoggingHandler(client,
                                    transport=BackgroundThreadTransport,
                                    name=...,
                                    resource=...,
                                    labels=...)

[skunkwerk]

thanks @crazystick, that almost worked for me... but I'm seeing logs from the background thread itself in my logs (ie. "submitted 1 logs" etc.) Is there any way to exclude that logger? google.cloud.logging.handlers.transports.background_thread

[crazystick]

There is a setup_logging function which you're supposed to use which excludes some internal logging. That function messes around with the root logger, so I do it manually like this. I find that adding the NullHandler is necessary or you end up with an extra StreamHandler which you might not want.

EXCLUDED_LOGGER_DEFAULTS = ("google.cloud", "google.auth", "google_auth_httplib2")

# don't propagate excluded loggers (and don't send them to stderr either)
for logger_name in EXCLUDED_LOGGER_DEFAULTS:
    logging.getLogger(logger_name).propagate = False
    logging.getLogger(logger_name).addHandler(logging.NullHandler())
    
# add cloud handler to root logger
logging.getLogger().addHandler(cloud_handler)

[Voyz]

Based on @crazystick 's answer, I use the following bodge to log custom objects as info payload. It derives more from the original _Worker.enqueue and supports passing custom fields.

from google.cloud.logging import _helpers
from google.cloud.logging.handlers.transports.background_thread import _Worker

def my_enqueue(self, record, message, resource=None, labels=None, trace=None, span_id=None):
    queue_entry = {
        "info": {"message": message, "python_logger": record.name},
        "severity": _helpers._normalize_severity(record.levelno),
        "resource": resource,
        "labels": labels,
        "trace": trace,
        "span_id": span_id,
        "timestamp": datetime.datetime.utcfromtimestamp(record.created),
    }

    if 'custom_fields' in record:
        entry['info']['custom_fields'] = record.custom_fields

    self._queue.put_nowait(queue_entry)

_Worker.enqueue = my_enqueue

Then

import logging
from google.cloud import logging as google_logging

logger = logging.getLogger('my_log_client')
logger.addHandler(CloudLoggingHandler(google_logging.Client(), 'my_log_client'))

logger.info('hello', extra={'custom_fields':{'foo': 1, 'bar':{'tzar':3}}})

Resulting in:

Which then makes it much easier to filter according to these custom_fields.

Naturally, it would be great if this would be naively supported - thanks in advance!

[a-mpch]

I tried to implement @Voyz solution on a Cloud Function and I couldn't make it work.
I think there is a strange behaviour with CF and monkey patching the module.

def my_enqueue(
    self, record, message, resource=None, labels=None, trace=None, span_id=None
):
    queue_entry = {
        "info": {
            "message": message,
            "python_logger": record.name,
            "error_fields": record.error_fields,
        },
        "severity": _helpers._normalize_severity(record.levelno),
        "resource": resource,
        "labels": labels,
        "trace": trace,
        "span_id": span_id,
        "timestamp": datetime.datetime.utcfromtimestamp(record.created),
    }
    self._queue.put_nowait(queue_entry)


_Worker.enqueue = my_enqueue

And the function...

def index(request):
    logger = logging.getLogger("my_log_client")
    handler = CloudLoggingHandler(
        logger_client, name="my_log_client", transport=BackgroundThreadTransport
    )
    logger.setLevel(logging.INFO)
    logger.addHandler(handler)
    logging.info("hello")
    logging.info("hello", extra={"custom_one": 1})
    logger.info("hello", extra={"error_fields": {"foo": 1, "bar": {"tzar": 3}}})
    return ("", 202)

I would expect some error if logging.info("hello") does not have the error_fields keys.
Is there any update if this will be implemented?

No errors :(

[snickell]

EDIT TO UPDATE, I've moved the gist into a repo and uploaded it to pypi:
https://github.com/snickell/google_structlog

pip install google-structlog

ORIGINAL for historical purposes:

I've extended @Voyz / @crazystick 's work, and built a pre-canned gist google_structlog:
https://gist.github.com/snickell/3b664c668b8a94d1ca6e31b0498a8697

• Uses structlog (https://www.structlog.org/en/stable/)
• Doesn't care how you use structlog, no particular naming constraints on extended attributes
• Results in structured + searchable JSON in stackdriver
• Preconfigured and works out of the box on GCP Debian 10 images with google-fluentd installed as per GCP instructions.

Its used like so:

import google_structlog

google_structlog.setup(log_name="here-is-mylilapp")

# Now you can use structlog to get searchable json details in stackdriver...
import structlog
logger = structlog.get_logger()
logger.error("Uhoh, something bad did", moreinfo="it was bad", years_back_luck=5)

# Of course, you can still use plain ol' logging stdlib to get { "message": ... } objects
import logging
logger = logging.getLogger("yoyo")
logger.error("Regular logging calls will work happily too")

# Now you can search stackdriver with the query:
# logName: 'here-is-mylilapp'

Which will produce a nice structured / searchable log inside GCP stackdriver:

Main difference with what @Voyz had posted is its somewhat structlog specific, and doesn't care what sort of extra values you pass. It also includes all the pre-canned bells and whistles to run out of the box, and shows you what to search for in GCP so you can work backwards to something that works for you but is working by default.

If there's interest, I can polish it a little further and put something up on pypi.

[numbsafari]

Seems like this would be something obvious and cough idiomatic to be included in this library. Stack Driver doesn't looks so hot next to Sentry without this capability out of the box.

[snickell]

Yeah, its a little frustrating to have "structured logging" with no simple ability to get in on it and inject your own domain-specific fields. That's where structured starts paying for its "not as easy to scan" downsides. The system provided structure fields are sort of 🤷‍♂️ compared to domain specific info that's super easy to create in code, and frustratingly hard to get into the log analysis tools in GCP.