Accept JSON fields from "extra" argument

[m-gentil]

Is your feature request related to a problem? Please describe.

When attaching the CloudLoggingHandler to a standard python logger, it is not possible to perform structured logging through the extra keyword argument for each logging call. Please refer to the standard logging python library for more documentation about the extra parameter. Take for instance the following snippet of code, written in Python 3.9 and using google-cloud-logging==2.6.0 as a dependency:

import logging
import google.cloud.logging
from google.cloud.logging_v2.handlers import CloudLoggingHandler

client = google.cloud.logging.Client()
handler = CloudLoggingHandler(client)

cloud_logger = logging.getLogger('cloudLogger')
cloud_logger.setLevel(logging.INFO)
cloud_logger.addHandler(handler)

cloud_logger.error('bad news', extra={"error_code": 300})  # Note that we include an extra dictionary

The extra dictionary is completely lost and does not appear in the received log from the Cloud Logging UI (see screenshot).

Describe the solution you'd like

All properties of a LogRecord that are considered as extras appear in the jsonPayload of the related entry in Cloud Logging. This can be implemented for instance in the body of the emit method of the CloudLoggingHandler (reference).

Describe alternatives you've considered

The only alternative solution we found is to use the log_struct method of the google.cloud.logging.logger.Logger() object directly. This is not a valid solution for us as we make heavy use of the standard logging library shipped with python: using a separate logger would introduce too much overhead for our existing and future projects, while killing the purpose of the centralized logging infrastructure that the python standard logging library provides.

Additional context

[daniel-sanche]

Hey, thanks for filing this

We are adding improved support for jsonPayload logs in the upcomming v3.0.0 release, which is currently staged in a branch in this repo. With v3, strings that contain parseable json will be rendered as structured json logs in Cloud Logging: cloud_logger.error(json.dumps(my_dict))

We also wrote logic in the library to handle dictionary inputs directly: cloud_logger.error(my_dict). But this method is counter to the python-logging spec (which expects string inputs) so JSON strings are recommended

I will leave this open to consider your suggestion of using the extras field for this purpose as well. We are currently using extras to allow over-writing other log entry fields, like trace, span, and labels. We may be able to throw any extra unrecognized extra fields in the json payload, but I'll have to think it over. Let me know if you think the method I described above works for your use-case

[m-gentil]

Hi Daniel 😄 ,

It's great to see that you are improving this functionality.
Unfortunately I fear that the method that you suggest is not optimal for us. In fact, we use different handlers to route logs to multiple destinations according to each environment (for instance, we stream logs to stdout / stderr when developing locally, while we stream logs to Cloud Logging when running applications in production).

Formatting structured logs as a JSON (cloud_logger.error(json.dumps(my_dict))) would render logs unreadable by other handlers (for example this would mean more prolix and less readable output when streaming logs to stdout / stderr or inspecting those messages for debugging purposes).

The only workaround that I can think of on our side would be to develop a custom Formatter to gather user-defined extra fields and formatting the message and its extras as a JSON. Then, we could attach this formatter to the CloudLoggingHandler so that the formatted JSON is later interpreted by the snippet of code you are mentioning.

Still, we would consider this as boilerplate code that we have to keep updated according to future changes in google-cloud-logging — this is suboptimal; furthermore we feel like this JSON serialization and successive deserialization introduces overhead that in many cases could be avoided.

That said, do we have any estimate on the release date for 3.0.0?

Please also let us know once you decide whether to go forward with this feature.

[daniel-sanche]

That makes sense, thanks. I'll do some research into the best way to do this - either including all unused extras in the json payload, or possibly accepting an explicit extra field (something like cloud_logger.error('bad news', extra={json_fields: my_dict}))

The hard deadline for v3.0.0 is the end of the year. But I'm planning to do some triage, and maybe bump some things to the next release to try to get it out sooner. I'll try to keep the milestone up to date with my plans

[stewart-r]

Hi,

We are also affected by this issue in much the same way as @m-gentil

I had a look and wonder if a good fix might be to extract this code, which maps from a LogRecord to the jsonPayload sent to cloud logging, from the enqueue() method on the _Worker class and bring it up into a dependency injected into the BackgroundThreadTransport class:

        queue_entry = {
            "info": {"message": message, "python_logger": record.name},
            "severity": _helpers._normalize_severity(record.levelno),
            "timestamp": datetime.datetime.utcfromtimestamp(record.created),
        }
        queue_entry.update(kwargs)

That way, we could override the behaviour when configuring logging in much the same way as we can do for setting custom log levels, cutom filters and the like.

So, for example, if the enqueue method was changed to just accept the queue_entry object directly and the BackgroundThreadTransport had another dependency with responsibility for mapping the LogRecord to a queue_entry then we could have something like this in our config order to override how the jsonPayload is created:

handler = client.get_default_handler(name="my-log")
handler.transport.payload_formatter = MyCustomPayloadFormatter()

where MyCustomPayloadFormatter is expected to inherit from an base PayloadFormatter class in the library and provides a single method to perform the mapping. Added a quick PR on my own fork to help visualise what I mean (just lmk if you want me to try and sort out the tests, etc and do a proper PR here).

[daniel-sanche]

Thanks for looking into it, but I think that might be the wrong layer to fix this at. BackgroundThreadTransport is used for sending asynchronous logs over grpc, but other customers use synchronous transport, or the http implementation, or the structured logging handler, so we'd have to implement it and maintain it in multiple places.

I think a better place to implement this is in the CloudLoggingFilter, which basically maps from python logging fields into GCP logentry fields. And then I may need to change some code in the individual handler classes as well.

I'm going to try to prioritize this to hopefully address it in the next week. But unfortunately since this is a larger change, it won't be released until v3.0.0 is ready later this quarter. But of course if you're comfortable installing off of a branch, you will be able to use it early that way.

I'll give an update here after it's implemented!

[stewart-r]

cool - thanks for responding.

For sure, it's better if that logic is outside the transport layer if that's feasible. Sounds great.

(only reason I had it in there in my proposed solution is because that's where it is now and so took the path of least resistance to surface it in an easily 'overrideable' place)