Open ankitarya1019 opened 5 months ago
@ankitarya1019 I've seen this issue on my end running something on GCE whose main function ends with a logging.info
call. Working on a fix right now.
I have the same issue when I configure Python logger for Cloud Function as advised on this page: https://cloud.google.com/logging/docs/setup/python
I am using Python 3.12.2
.
Here is the stack trace:
Program shutting down, attempting to send 6 queued log entries to Cloud Logging...
Waiting up to 5 seconds.
Failed to submit 6 logs.
Traceback (most recent call last):
File "/home/tsaluszewski/code/refurbed/analytics-pipelines/.venv/lib/python3.12/site-packages/google/cloud/logging_v2/handlers/transports/background_thread.py", line 115, in _safely_commit_batch
batch.commit()
File "/home/tsaluszewski/code/refurbed/analytics-pipelines/.venv/lib/python3.12/site-packages/google/cloud/logging_v2/logger.py", line 467, in commit
client.logging_api.write_entries(
File "/home/tsaluszewski/code/refurbed/analytics-pipelines/.venv/lib/python3.12/site-packages/google/cloud/logging_v2/_gapic.py", line 163, in write_entries
self._gapic_api.write_log_entries(request=request)
File "/home/tsaluszewski/code/refurbed/analytics-pipelines/.venv/lib/python3.12/site-packages/google/cloud/logging_v2/services/logging_service_v2/client.py", line 727, in write_log_entries
response = rpc(
^^^^
File "/home/tsaluszewski/code/refurbed/analytics-pipelines/.venv/lib/python3.12/site-packages/google/api_core/gapic_v1/method.py", line 131, in __call__
return wrapped_func(*args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/home/tsaluszewski/code/refurbed/analytics-pipelines/.venv/lib/python3.12/site-packages/google/api_core/retry/retry_unary.py", line 293, in retry_wrapped_func
return retry_target(
^^^^^^^^^^^^^
File "/home/tsaluszewski/code/refurbed/analytics-pipelines/.venv/lib/python3.12/site-packages/google/api_core/retry/retry_unary.py", line 153, in retry_target
_retry_error_helper(
File "/home/tsaluszewski/code/refurbed/analytics-pipelines/.venv/lib/python3.12/site-packages/google/api_core/retry/retry_base.py", line 212, in _retry_error_helper
raise final_exc from source_exc
File "/home/tsaluszewski/code/refurbed/analytics-pipelines/.venv/lib/python3.12/site-packages/google/api_core/retry/retry_unary.py", line 144, in retry_target
result = target()
^^^^^^^^
File "/home/tsaluszewski/code/refurbed/analytics-pipelines/.venv/lib/python3.12/site-packages/google/api_core/timeout.py", line 120, in func_with_timeout
return func(*args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^
File "/home/tsaluszewski/code/refurbed/analytics-pipelines/.venv/lib/python3.12/site-packages/google/api_core/grpc_helpers.py", line 76, in error_remapped_callable
return callable_(*args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/home/tsaluszewski/code/refurbed/analytics-pipelines/.venv/lib/python3.12/site-packages/grpc/_channel.py", line 1157, in __call__
) = self._blocking(
^^^^^^^^^^^^^^^
File "/home/tsaluszewski/code/refurbed/analytics-pipelines/.venv/lib/python3.12/site-packages/grpc/_channel.py", line 1141, in _blocking
event = call.next_event()
^^^^^^^^^^^^^^^^^
File "src/python/grpcio/grpc/_cython/_cygrpc/channel.pyx.pxi", line 366, in grpc._cython.cygrpc.SegregatedCall.next_event
File "src/python/grpcio/grpc/_cython/_cygrpc/channel.pyx.pxi", line 187, in grpc._cython.cygrpc._next_call_event
File "src/python/grpcio/grpc/_cython/_cygrpc/channel.pyx.pxi", line 181, in grpc._cython.cygrpc._next_call_event
File "src/python/grpcio/grpc/_cython/_cygrpc/completion_queue.pyx.pxi", line 78, in grpc._cython.cygrpc._latent_event
File "src/python/grpcio/grpc/_cython/_cygrpc/completion_queue.pyx.pxi", line 61, in grpc._cython.cygrpc._internal_latent_event
File "src/python/grpcio/grpc/_cython/_cygrpc/credentials.pyx.pxi", line 62, in grpc._cython.cygrpc._get_metadata
File "src/python/grpcio/grpc/_cython/_cygrpc/credentials.pyx.pxi", line 28, in grpc._cython.cygrpc._spawn_callback_async
File "src/python/grpcio/grpc/_cython/_cygrpc/credentials.pyx.pxi", line 19, in grpc._cython.cygrpc._spawn_callback_in_thread
File "src/python/grpcio/grpc/_cython/_cygrpc/fork_posix.pyx.pxi", line 120, in grpc._cython.cygrpc.ForkManagedThread.start
File "/home/tsaluszewski/.pyenv/versions/3.12.2/lib/python3.12/threading.py", line 992, in start
_start_new_thread(self._bootstrap, ())
RuntimeError: can't create new thread at interpreter shutdown
Sent all pending logs.
@tsaluszewski Could you post the script that you used to get the stack trace? I've been able to reproduce it on my end and I'm just curious what you did. Since you followed the quick start guide, is it something along the lines of
# 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()
# Imports Python standard library logging
import logging
# The data to log
text = "Hello, world!"
# Emits the data using the standard logging module
logging.warning(text)
@tsaluszewski Could you post the script that you used to get the stack trace? I've been able to reproduce it on my end and I'm just curious what you did. Since you followed the quick start guide, is it something along the lines of
Yes, very similar, see below my logging
module that I am using from every Cloud Function.
I got an error on client.setup_logging
, and neither of the logs from the application got emitted.
logger.py
:
import logging
from logging import Logger
LOG_FORMAT = "%(asctime)s |%(levelname)s| (%(module)s):%(lineno)s >> %(message)s"
def setup_logger(log_level: str, enable_cloud_logging: bool) -> Logger:
"""
Setup root logger only once, module level loggers will inherit its configuration.
:param log_level: logging level
:param enable_cloud_logging: whether to enable google cloud logging
:returns: pre-configured root logger
"""
if enable_cloud_logging:
setup_cloud_logging(log_level)
logging.basicConfig(format=LOG_FORMAT, level=log_level)
logger = logging.getLogger()
return logger
def setup_cloud_logging(log_level: str) -> None:
"""
Attach the Cloud Logging handler to the Python root logger as described below:
- https://cloud.google.com/logging/docs/setup/python
:param log_level: logging level
"""
from google.cloud.logging import Client
# Instantiates a client
client = Client()
# Retrieves a Cloud Logging handler based on the environment you're running in
# and integrates the handler with the Python logging module
client.setup_logging(log_level=log_level)
Notes:
client
as module level variable or not (same error)main.py
:
import functions_framework
from common.logger import setup_logger
from common.models import Config
from common.typings import EventRequest
config = Config()
logger = setup_logger(config.log_level, config.is_cloud)
@functions_framework.http
def run(request: EventRequest) -> str:
"""
Function entry point.
:param request: request payload
"""
logger.info(f"Invoked with event={str(request)}")
....
@tsaluszewski I wasn't able to reproduce this deploying on Cloud Functions, as setup_logging
resolves to StructuredLogHandler
, but locally and when setup_logging
resolves to CloudLoggingHandler
, this is the same bug.
This is still presenting an issue. My gross workaround for now it is to stick a sleep(10)
on the end of my main. Its ok for me as it a service that runs nightly, and I dont really care about the time it takes, but it would be nice if I didn't have to throw this in there.
Environment details
Cloud Run with google-cloud-logging==3.9.0
Steps to reproduce
Code example
Stack trace
most similar issue I could find: https://github.com/googleapis/python-logging/issues/21. but there is no clear resolution