Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

RuntimeError: can't create new thread at interpreter shutdown #850

Open
ankitarya1019 opened this issue Feb 2, 2024 · 5 comments
Open
Assignees
Labels
api: logging Issues related to the googleapis/python-logging API. priority: p3 Desirable enhancement or fix. May not be included in next release. type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns.

Comments

@ankitarya1019
Copy link

Environment details

Cloud Run with google-cloud-logging==3.9.0

Steps to reproduce

  1. main.py from here: https://cloud.google.com/run/docs/quickstarts/jobs/build-create-python
    (print statements swapped with logger.info )
  2. 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 process

Stack 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

@product-auto-label product-auto-label bot added the api: logging Issues related to the googleapis/python-logging API. label Feb 2, 2024
@gkevinzheng
Copy link
Contributor

@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.

@gkevinzheng gkevinzheng added type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns. priority: p3 Desirable enhancement or fix. May not be included in next release. labels Feb 7, 2024
@tsaluszewski
Copy link

tsaluszewski commented Feb 16, 2024

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.

@gkevinzheng
Copy link
Contributor

@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
Copy link

tsaluszewski commented Feb 27, 2024

@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:

  • It does not matter whether I declare client as module level variable or not (same error)
  • I can reproduce the error while running from my local machine

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)}")
   ....

@gkevinzheng
Copy link
Contributor

@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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
api: logging Issues related to the googleapis/python-logging API. priority: p3 Desirable enhancement or fix. May not be included in next release. type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns.
Projects
None yet
Development

No branches or pull requests

3 participants