"Warning" is being published as "Error"

[arslanov-test]

Summary

In commit (https://github.com/GoogleCloudPlatform/cloud-profiler-python/commit/814731125216fd1c332c9d90074635485e8ac62f#diff-6bc78e58322668fa0a7c4d34928f7647f75ac41852c8df1ee3e3aee2fd422966), you have changed log.error to log.warning. However, it seems that GCP Cloud Logging will take this as "Error" anyway since python's logging library is not fully respected[1]. There is an internal issue on this inside Google[2].

To heal this issue, we should import google.cloud.logging library. Please see the below reproducing steps.

Reproducing steps

I have tried to run following in Cloud Functions and "Error" came out anyway instead of "Warning" in Cloud Logging:

main.py:

import logging

logger = logging.getLogger(__name__)

def hello_world(request):
  logger.warning("this is warning")

requirements.txt:

google-cloud-logging>=2.7.0

After I added google.cloud.logging as follows, the warning has been published as "Warning" in cloud logging:

main.py:

import logging

import google.cloud.logging # Don't conflict with standard logging
client = google.cloud.logging.Client()
client.setup_logging()

logger = logging.getLogger(__name__)

def hello_world(request):
  logger.warning("this is warning")

Request to the team

1. Could you please check the above hypothesis and let me know whether I am right or not?
2. If so, could you fix this accordingly so that "Warning" in backoff file is published as "Warning" in Cloud Logging?

[1]. https://stackoverflow.com/questions/65776399/why-is-my-gcp-function-logging-errors-that-should-be-info-or-debug [2]. https://issuetracker.google.com/124403972

[minherz]

@arslanov-test thank you for letting us know about the problem and providing the detailed response. The only missing bits are a configuration of the python logger and the details about the environment where you run your program. All serverless environments in Google Cloud, GKE and GCE VMs that have logging agent installed can capture application output to stdout and stderr. According to your description it looks like the calls to logger.warning() are printed to stderr, hence they are ingested with the severity error. If you would like to control the severity of the logs that you print to stdout and expected to be captured, you should use structured logging. The Google client library for logging (in Python) is yet to support this feature in the next release.

The "working" version overrides the behavior of the standard Python logging. Thus you see the different behavior.

Addressing your questions:

1. Could you please check the above hypothesis and let me know whether I am right or not?

Your hypothesis provides one of the possible ways to solve this problem (in Cloud Function). Another is to print to stdout a well formed Json string following instructions for the structured logging.

2. If so, could you fix this accordingly so that "Warning" in backoff file is published as "Warning" in Cloud Logging?

Would you mind to explain what functionality you are looking for? I am not familiar with the term "backoff file" that you used.

[arslanov-test]

@minherz Thank you for your kind reply. Let me introduce my issue: I am running cloud-profiler-python in dataflow and have seen that warning in [1] has been published as error in cloud logging. I want this message to be published as warning.

Afterwards, I have tried to reproduce the issue by running the python file in Cloud Functions with the code I provided in the first comment (I tried to import logging library as you did) and found that logging.warning is being published as "Error". Therefore, I came to conclusion that although you have changed from logger.error to logger.warning in [2], anyway error comes out with the message[3].

Therefore, I think you should fix the code in backoff.py[4] (e.g. adding google.cloud.logging as I did) so that [5] is published as "warning" in GCP VMs. Could you fix it?

[1]. https://github.com/GoogleCloudPlatform/cloud-profiler-python/blob/main/googlecloudprofiler/backoff.py#L82-L85 [2]. https://github.com/GoogleCloudPlatform/cloud-profiler-python/commit/814731125216fd1c332c9d90074635485e8ac62f#diff-6bc78e58322668fa0a7c4d34928f7647f75ac41852c8df1ee3e3aee2fd422966R83 [3]. Failed to extract server-specified backoff duration [4]. https://github.com/GoogleCloudPlatform/cloud-profiler-python/blob/814731125216fd1c332c9d90074635485e8ac62f/googlecloudprofiler/backoff.py [5]. https://github.com/GoogleCloudPlatform/cloud-profiler-python/blob/814731125216fd1c332c9d90074635485e8ac62f/googlecloudprofiler/backoff.py#L83

[arslanov-test]

How can I modify your code in [1] (e.g. by adding structured logging or using google.cloud.logging) and use it in Cloud Dataflow so that [2] is published as warning? Should I use custom package way?

[1]. https://github.com/GoogleCloudPlatform/cloud-profiler-python/blob/814731125216fd1c332c9d90074635485e8ac62f/googlecloudprofiler/backoff.py [2]. https://github.com/GoogleCloudPlatform/cloud-profiler-python/blob/814731125216fd1c332c9d90074635485e8ac62f/googlecloudprofiler/backoff.py#L83

[tswast]

If you want to use the standard logging module, the google-cloud-logging library provides a custom handler that writes structured logs instead.

# Imports the Cloud Logging client library
import google.cloud.logging

# Instantiates a client
client = google.cloud.logging.Client()

# Retrieves a Cloud Logging handler based on the environment
# you're running in and integrates the handler with the
# Python logging module. By default this captures all logs
# at INFO level and higher
client.setup_logging()

https://cloud.google.com/logging/docs/setup/python

[tswast]

Note re: https://github.com/GoogleCloudPlatform/cloud-profiler-python/issues/106#issuecomment-999898498, since the Cloud Profiler Agent is intended to be run in places other than GCP, you may not want to take on google-cloud-logging as a required dependency. Either way though, an option to enable structured logging seems useful.

[tswast]

@arslanov-test Does adding the snippet from your issue description

import google.cloud.logging # Don't conflict with standard logging
client = google.cloud.logging.Client()
client.setup_logging()

to your code before enabling profiling solve your issue?

I'm not sure what changes you are expecting from the Cloud Profiler team. It doesn't make much sense to me to have it always send logs to Cloud Logging, since the product can be used in environments other than GCP.

[aalexand]

The profiler agent is also just a library - things like client.setup_logging() feel more suitable for the application main() function, not for a library to control.

[arslanov-test]

Thank you team for your replies. I understood.