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.

Sign up for GitHub

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

Jump to bottom

google.cloud.logging: RuntimeError: cannot schedule new futures after shutdown #21

Closed
ael-computas opened this issue Feb 11, 2020 · 7 comments
Closed

google.cloud.logging: RuntimeError: cannot schedule new futures after shutdown #21

ael-computas opened this issue Feb 11, 2020 · 7 comments
Assignees
@daniel-sanche
Labels
api: logging Issues related to the googleapis/python-logging API. priority: p2 Moderately-important priority. Fix may not be included in next release. type: cleanup An internal cleanup or hygiene concern.
Milestone
v2 Update 3

Comments

@ael-computas
Copy link

I keep receiving this exception on program shutdown and I cant figure out what to do to make a clean shutdown

Minimal code of main.py is something like this

logging.basicConfig(
    level=logging.getLevelName(logging.getLevelName("INFO")),
    format="%(asctime)s - %(name)s - [%(levelname)-5.5s]  %(message)s",
    handlers={
        logging.FileHandler("import_from_gcs_path.log")
    }
)
client = google.cloud.logging.Client()
client.setup_logging(name="example")

if __name__ == '__main__':
    logging.info(f"Importing file to platform.")
    # Some business code here, using gcs/datastore - no threading.
    logging.shutdown()
@ael-computas ael-computas changed the title RuntimeError: cannot schedule new futures after shutdown Stackdriver: RuntimeError: cannot schedule new futures after shutdown Feb 11, 2020
@ael-computas ael-computas changed the title Stackdriver: RuntimeError: cannot schedule new futures after shutdown google.cloud.logging: RuntimeError: cannot schedule new futures after shutdown Feb 11, 2020
@busunkim96 busunkim96 transferred this issue from googleapis/google-cloud-python Feb 11, 2020
@product-auto-label product-auto-label bot added the api: logging Issues related to the googleapis/python-logging API. label Feb 11, 2020
@busunkim96
Copy link
Contributor

@ael-computas Could you let us know what exception you are seeing? I don't see it in the example code. Thanks!

@yoshi-automation yoshi-automation added the triage me I really want to be triaged. label Feb 11, 2020
@TanGolf
Copy link

TanGolf commented Feb 12, 2020

I am also experiencing this. It seems that despite the "Waiting up to 5 seconds." message, if you don't block the main thread after calling the logging functions you will get a RuntimeException. See stack trace below:

Traceback (most recent call last):
  File "C:\Users\Tristan\.virtualenvs\FileUploadSubscriber-xLr_mn81\lib\site-packages\grpc\_plugin_wrapping.py", line 78, in __call__
    context, _AuthMetadataPluginCallback(callback_state, callback))
  File "C:\Users\Tristan\.virtualenvs\FileUploadSubscriber-xLr_mn81\lib\site-packages\google\auth\transport\grpc.py", line 87, in __call__
    future = self._pool.submit(self._get_authorization_headers, context)
  File "C:\Users\Tristan\AppData\Local\Programs\Python\Python37-32\Lib\concurrent\futures\thread.py", line 165, in submit
    raise RuntimeError('cannot schedule new futures after '
RuntimeError: cannot schedule new futures after interpreter shutdown
grpc._plugin_wrapping - ERROR - AuthMetadataPluginCallback "<google.auth.transport.grpc.AuthMetadataPlugin object at 0x042B64D0>" raised exception!  
Traceback (most recent call last):
  File "C:\Users\Tristan\.virtualenvs\FileUploadSubscriber-xLr_mn81\lib\site-packages\grpc\_plugin_wrapping.py", line 78, in __call__
    context, _AuthMetadataPluginCallback(callback_state, callback))
  File "C:\Users\Tristan\.virtualenvs\FileUploadSubscriber-xLr_mn81\lib\site-packages\google\auth\transport\grpc.py", line 87, in __call__
    future = self._pool.submit(self._get_authorization_headers, context)
  File "C:\Users\Tristan\AppData\Local\Programs\Python\Python37-32\Lib\concurrent\futures\thread.py", line 165, in submit
    raise RuntimeError('cannot schedule new futures after '
RuntimeError: cannot schedule new futures after interpreter shutdown
Failed to send 12 pending logs.

To see if it was due to the main thread shutting down before the background threads had completed processing I added some additional code which then allowed the logging to complete and it then succeeded:

import logging
import logging.config
import yaml
import time

with open('logger/config.yaml', 'r') as f:
    config = yaml.safe_load(f.read())
    logging.config.dictConfig(config)

logger = logging.getLogger(__name__)

# comment these out and then  comment them in one-by-one. Once the 'warn' line is in it starts failing. 
logger.debug("--debug--")
logger.info("--info--")
logger.warning("--warn--")
logger.error("--error--")
logger.critical("--critical--")

# without this block, we get the RuntimeError
try:
    while True:
        time.sleep(1)
except KeyboardInterrupt:
    print("Shutting main thread down")

An additional, but very peculiar point, is that most of the time the logging works fine until I log a WARNING level log, after which the problem is exacerbated. May just be coincidence though.

@busunkim96 busunkim96 added type: cleanup An internal cleanup or hygiene concern. and removed triage me I really want to be triaged. labels Feb 14, 2020
@busunkim96
Copy link
Contributor

@TanGolf Thank you for the additional details. Are you running the logging client in a multi-threaded environment?

@TanGolf
Copy link

TanGolf commented Feb 14, 2020 •
edited
Loading

@busunkim96 No problem. Yes, that is correct.

@leberknecht
Copy link

Had similar problems, as an workaround i added time.sleep(1) in the end of the script, which solved the problem. Just as a side-note.

@daniel-sanche daniel-sanche added this to the v.2.3.0 milestone Jan 27, 2021
@keenan-devrel keenan-devrel added the priority: p2 Moderately-important priority. Fix may not be included in next release. label Jan 29, 2021
@daniel-sanche
Copy link
Contributor

I tried running the provided code, but couldn't reproduce it. Since this is a year-old issue and we've released a number of updates since, I'm going to close this. If anyone still sees the issue, feel free to re-open and I can look at it again

@ankitarya1019
Copy link

Running into a similar issue when using cloud run.

the Cloud Run job is right from the official example here: https://cloud.google.com/run/docs/quickstarts/jobs/build-create-python
where print statements where switched with google pythong logging module

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/[email protected]/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).

@ankitarya1019 ankitarya1019 mentioned this issue Feb 2, 2024
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@daniel-sanche daniel-sanche

Labels
api: logging Issues related to the googleapis/python-logging API. priority: p2 Moderately-important priority. Fix may not be included in next release. type: cleanup An internal cleanup or hygiene concern.
Projects
None yet
Milestone
v2 Update 3
Development

No branches or pull requests
8 participants
@leberknecht @daniel-sanche @TanGolf @busunkim96 @ael-computas @yoshi-automation @ankitarya1019 @keenan-devrel