Open
Description
Environment details
Cloud Run with google-cloud-logging==3.9.0
Steps to reproduce
- main.py from here: https://cloud.google.com/run/docs/quickstarts/jobs/build-create-python
(print statements swapped with logger.info ) - settings.py that sets up google logging:
# Imports the Cloud Logging client library
import google.cloud.logging
# Imports Python standard library logging
import 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()
logging_level = logging.DEBUG
main_logger = logging.getLogger()
main_logger.setLevel(logging_level)
# Set up a stream handler to log to the console
stream_handler = logging.StreamHandler()
stream_handler.setLevel(logging_level)
formatter = logging.Formatter("%(name)s - %(levelname)s - %(message)s")
stream_handler.setFormatter(formatter)
# Add handler to logger
main_logger.addHandler(stream_handler)
Code example
import settings
import logging
import json
import os
import random
import sys
import time
logger = logging.getLogger(__name__)
# Retrieve Job-defined env vars
TASK_INDEX = os.getenv("CLOUD_RUN_TASK_INDEX", 0)
TASK_ATTEMPT = os.getenv("CLOUD_RUN_TASK_ATTEMPT", 0)
# Retrieve User-defined env vars
SLEEP_MS = os.getenv("SLEEP_MS", 0)
FAIL_RATE = os.getenv("FAIL_RATE", 0)
# Define main script
def main(sleep_ms=0, fail_rate=0):
"""Program that simulates work using the sleep method and random failures.
Args:
sleep_ms: number of milliseconds to sleep
fail_rate: rate of simulated errors
"""
logger.info(f"Starting Task #{TASK_INDEX}, Attempt #{TASK_ATTEMPT}...")
# Simulate work by waiting for a specific amount of time
time.sleep(float(sleep_ms) / 1000) # Convert to seconds
# Simulate errors
random_failure(float(fail_rate))
logger.info(f"Completed Task #{TASK_INDEX}.")
def random_failure(rate):
"""Throws an error based on fail rate
Args:
rate: an integer between 0 and 1
"""
if rate < 0 or rate > 1:
# Return without retrying the Job Task
logger.info(
f"Invalid FAIL_RATE env var value: {rate}. "
+ "Must be a float between 0 and 1 inclusive."
)
return
random_failure = random.random()
if random_failure < rate:
raise Exception("Task failed.")
# Start script
if __name__ == "__main__":
try:
main(SLEEP_MS, FAIL_RATE)
except Exception as err:
message = (
f"Task #{TASK_INDEX}, " + f"Attempt #{TASK_ATTEMPT} failed: {str(err)}"
)
logger.info(json.dumps({"message": message, "severity": "ERROR"}))
sys.exit(1) # Retry Job Task by exiting the processStack trace
2024-02-02 12:53:32.029 PST
__main__ - INFO - Starting Task #1, Attempt #0...
2024-02-02 12:53:32.092 PST
urllib3.connectionpool - DEBUG - Starting new HTTP connection (1): metadata.google.internal:80
2024-02-02 12:53:32.093 PST
urllib3.connectionpool - DEBUG - http://metadata.google.internal:80 "GET /computeMetadata/v1/instance/service-accounts/default/?recursive=true HTTP/1.1" 200 626
2024-02-02 12:53:32.114 PST
urllib3.connectionpool - DEBUG - http://metadata.google.internal:80 "GET /computeMetadata/v1/instance/service-accounts/267066844436-compute@developer.gserviceaccount.com/token?scopes=https%3A%2F%2Fwww.googleapis.com%2Fauth%2Flogging.read%2Chttps%3A%2F%2Fwww.googleapis.com%2Fauth%2Flogging.write%2Chttps%3A%2F%2Fwww.googleapis.com%2Fauth%2Flogging.admin%2Chttps%3A%2F%2Fwww.googleapis.com%2Fauth%2Fcloud-platform HTTP/1.1" 200 1083
2024-02-02 12:53:42.030 PST
__main__ - INFO - Completed Task #1.
2024-02-02 12:53:42.030 PST
Program shutting down, attempting to send 1 queued log entries to Cloud Logging...
2024-02-02 12:53:42.031 PST
Waiting up to 5 seconds.
2024-02-02 12:53:42.064 PST
Failed to submit 1 logs.
2024-02-02 12:53:42.064 PST
Traceback (most recent call last): File "/layers/google.python.pip/pip/lib/python3.12/site-packages/google/cloud/logging_v2/handlers/transports/background_thread.py", line 115, in _safely_commit_batch batch.commit() File "/layers/google.python.pip/pip/lib/python3.12/site-packages/google/cloud/logging_v2/logger.py", line 467, in commit client.logging_api.write_entries( File "/layers/google.python.pip/pip/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 "/layers/google.python.pip/pip/lib/python3.12/site-packages/google/cloud/logging_v2/services/logging_service_v2/client.py", line 727, in write_log_entries response = rpc(
2024-02-02 12:53:42.064 PST
^^^^
2024-02-02 12:53:42.064 PST
File "/layers/google.python.pip/pip/lib/python3.12/site-packages/google/api_core/gapic_v1/method.py", line 131, in __call__
2024-02-02 12:53:42.064 PST
return wrapped_func(*args, **kwargs)
2024-02-02 12:53:42.064 PST
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-02-02 12:53:42.064 PST
File "/layers/google.python.pip/pip/lib/python3.12/site-packages/google/api_core/retry/retry_unary.py", line 293, in retry_wrapped_func
2024-02-02 12:53:42.064 PST
return retry_target(
2024-02-02 12:53:42.064 PST
^^^^^^^^^^^^^
2024-02-02 12:53:42.064 PST
File "/layers/google.python.pip/pip/lib/python3.12/site-packages/google/api_core/retry/retry_unary.py", line 153, in retry_target
2024-02-02 12:53:42.064 PST
_retry_error_helper(
2024-02-02 12:53:42.064 PST
File "/layers/google.python.pip/pip/lib/python3.12/site-packages/google/api_core/retry/retry_base.py", line 212, in _retry_error_helper
2024-02-02 12:53:42.064 PST
raise final_exc from source_exc
2024-02-02 12:53:42.064 PST
File "/layers/google.python.pip/pip/lib/python3.12/site-packages/google/api_core/retry/retry_unary.py", line 144, in retry_target
2024-02-02 12:53:42.064 PST
result = target()
2024-02-02 12:53:42.064 PST
^^^^^^^^
2024-02-02 12:53:42.064 PST
File "/layers/google.python.pip/pip/lib/python3.12/site-packages/google/api_core/timeout.py", line 120, in func_with_timeout
2024-02-02 12:53:42.064 PST
return func(*args, **kwargs)
2024-02-02 12:53:42.064 PST
^^^^^^^^^^^^^^^^^^^^^
2024-02-02 12:53:42.064 PST
File "/layers/google.python.pip/pip/lib/python3.12/site-packages/google/api_core/grpc_helpers.py", line 79, in error_remapped_callable
2024-02-02 12:53:42.064 PST
return callable_(*args, **kwargs)
2024-02-02 12:53:42.064 PST
^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-02-02 12:53:42.064 PST
File "/layers/google.python.pip/pip/lib/python3.12/site-packages/grpc/_channel.py", line 1157, in __call__
2024-02-02 12:53:42.064 PST
) = self._blocking(
2024-02-02 12:53:42.064 PST
^^^^^^^^^^^^^^^
2024-02-02 12:53:42.064 PST
File "/layers/google.python.pip/pip/lib/python3.12/site-packages/grpc/_channel.py", line 1126, in _blocking
2024-02-02 12:53:42.064 PST
call = self._channel.segregated_call(
2024-02-02 12:53:42.064 PST
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-02-02 12:53:42.064 PST
File "src/python/grpcio/grpc/_cython/_cygrpc/channel.pyx.pxi", line 524, in grpc._cython.cygrpc.Channel.segregated_call
2024-02-02 12:53:42.064 PST
File "src/python/grpcio/grpc/_cython/_cygrpc/channel.pyx.pxi", line 394, in grpc._cython.cygrpc._segregated_call
2024-02-02 12:53:42.064 PST
File "src/python/grpcio/grpc/_cython/_cygrpc/channel.pyx.pxi", line 388, in grpc._cython.cygrpc._segregated_call
2024-02-02 12:53:42.064 PST
File "src/python/grpcio/grpc/_cython/_cygrpc/channel.pyx.pxi", line 236, in grpc._cython.cygrpc._call
2024-02-02 12:53:42.064 PST
File "src/python/grpcio/grpc/_cython/_cygrpc/channel.pyx.pxi", line 267, in grpc._cython.cygrpc._call
2024-02-02 12:53:42.064 PST
File "src/python/grpcio/grpc/_cython/_cygrpc/credentials.pyx.pxi", line 62, in grpc._cython.cygrpc._get_metadata
2024-02-02 12:53:42.064 PST
File "src/python/grpcio/grpc/_cython/_cygrpc/credentials.pyx.pxi", line 28, in grpc._cython.cygrpc._spawn_callback_async
2024-02-02 12:53:42.064 PST
File "src/python/grpcio/grpc/_cython/_cygrpc/credentials.pyx.pxi", line 19, in grpc._cython.cygrpc._spawn_callback_in_thread
2024-02-02 12:53:42.064 PST
File "src/python/grpcio/grpc/_cython/_cygrpc/fork_posix.pyx.pxi", line 120, in grpc._cython.cygrpc.ForkManagedThread.start
2024-02-02 12:53:42.064 PST
File "/layers/google.python.runtime/python/lib/python3.12/threading.py", line 992, in start
2024-02-02 12:53:42.064 PST
_start_new_thread(self._bootstrap, ())
2024-02-02 12:53:42.064 PST
RuntimeError: can't create new thread at interpreter shutdown
2024-02-02 12:53:42.064 PST
Sent all pending logs.
2024-02-02 12:53:42.182 PST
Container called exit(0).
most similar issue I could find: #21. but there is no clear resolution