Write entries is failing with Deadline Exceeded error

[chrisK824]

Lately, we have been facing logging failures due to 504 Deadline exceeded errors. (stacktrace at the end of issue). It seems to me that failure has probably nothing to do with the library itself, rather than network/server issue at sporadic times, although I haven't dived too deep to check what this InactiveRPC error really means. In case of just network error, the library might need to be enhanced to expose retry argument, so that one can tweak with that while using the client? Meanwhile, the errors suggest that the library still tries to write the log for more than 1 minute, which can cause a request to timeout in App Engine, as this is the upper limit for response time. Am I missing something here?

Environment details

OS Type and Version: App Engine Standard Environment
Python Version: 3.11
pip Version: Not sure what app engine uses
google-cloud-logging Version: 3.5.0

Steps to reproduce

1. Deploy an App Engine application with google-cloud-logging and uwsgi as the server.
2. Access the application and generate some logs.

Code example

# Nothing to add really here, just using normally the library as always. Nothing fancy.

Stack trace

DEFAULT 2024-03-13T01:10:18.022921Z Failed to submit 1 logs.
ERROR 2024-03-13T01:10:18.022951Z Traceback (most recent call last): File "/layers/google.python.pip/pip/lib/python3.11/site-packages/google/api_core/grpc_helpers.py", line 75, in error_remapped_callable return callable_(*args, **kwargs)
DEFAULT 2024-03-13T01:10:18.022955Z ^^^^^^^^^^^^^^^^^^^^^^^^^^
DEFAULT 2024-03-13T01:10:18.022961Z File "/layers/google.python.pip/pip/lib/python3.11/site-packages/grpc/_channel.py", line 1161, in __call__
DEFAULT 2024-03-13T01:10:18.022966Z return _end_unary_response_blocking(state, call, False, None)
DEFAULT 2024-03-13T01:10:18.022970Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
DEFAULT 2024-03-13T01:10:18.022975Z File "/layers/google.python.pip/pip/lib/python3.11/site-packages/grpc/_channel.py", line 1004, in _end_unary_response_blocking
DEFAULT 2024-03-13T01:10:18.022980Z raise _InactiveRpcError(state) # pytype: disable=not-instantiable
DEFAULT 2024-03-13T01:10:18.022984Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
DEFAULT 2024-03-13T01:10:18.022993Z grpc._channel._InactiveRpcError: <_InactiveRpcError of RPC that terminated with:
DEFAULT 2024-03-13T01:10:18.022995Z status = StatusCode.DEADLINE_EXCEEDED
DEFAULT 2024-03-13T01:10:18.022999Z details = "Deadline Exceeded"
DEFAULT 2024-03-13T01:10:18.023005Z debug_error_string = "UNKNOWN:Deadline Exceeded {grpc_status:4, created_time:"2024-03-13T01:10:17.99633522+00:00"}"
DEFAULT 2024-03-13T01:10:18.023009Z >
DEFAULT 2024-03-13T01:10:18.023017Z The above exception was the direct cause of the following exception:
ERROR 2024-03-13T01:10:18.023025Z Traceback (most recent call last): File "/layers/google.python.pip/pip/lib/python3.11/site-packages/google/api_core/retry.py", line 207, in retry_target result = target()
DEFAULT 2024-03-13T01:10:18.023027Z ^^^^^^^^
DEFAULT 2024-03-13T01:10:18.023032Z File "/layers/google.python.pip/pip/lib/python3.11/site-packages/google/api_core/timeout.py", line 120, in func_with_timeout
DEFAULT 2024-03-13T01:10:18.023035Z return func(*args, **kwargs)
DEFAULT 2024-03-13T01:10:18.023039Z ^^^^^^^^^^^^^^^^^^^^^
DEFAULT 2024-03-13T01:10:18.023044Z File "/layers/google.python.pip/pip/lib/python3.11/site-packages/google/api_core/grpc_helpers.py", line 77, in error_remapped_callable
DEFAULT 2024-03-13T01:10:18.023048Z raise exceptions.from_grpc_error(exc) from exc
DEFAULT 2024-03-13T01:10:18.023055Z google.api_core.exceptions.DeadlineExceeded: 504 Deadline Exceeded
DEFAULT 2024-03-13T01:10:18.023060Z The above exception was the direct cause of the following exception:
ERROR 2024-03-13T01:10:18.023071Z Traceback (most recent call last): File "/layers/google.python.pip/pip/lib/python3.11/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.11/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.11/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.11/site-packages/google/cloud/logging_v2/services/logging_service_v2/client.py", line 727, in write_log_entries response = rpc(
DEFAULT 2024-03-13T01:10:18.023073Z ^^^^
DEFAULT 2024-03-13T01:10:18.023078Z File "/layers/google.python.pip/pip/lib/python3.11/site-packages/google/api_core/gapic_v1/method.py", line 131, in __call__
DEFAULT 2024-03-13T01:10:18.023082Z return wrapped_func(*args, **kwargs)
DEFAULT 2024-03-13T01:10:18.023086Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
DEFAULT 2024-03-13T01:10:18.023091Z File "/layers/google.python.pip/pip/lib/python3.11/site-packages/google/api_core/retry.py", line 372, in retry_wrapped_func
DEFAULT 2024-03-13T01:10:18.023095Z return retry_target(
DEFAULT 2024-03-13T01:10:18.023099Z ^^^^^^^^^^^^^
DEFAULT 2024-03-13T01:10:18.023103Z File "/layers/google.python.pip/pip/lib/python3.11/site-packages/google/api_core/retry.py", line 226, in retry_target
DEFAULT 2024-03-13T01:10:18.023107Z raise exceptions.RetryError(
DEFAULT 2024-03-13T01:10:19.041498Z google.api_core.exceptions.RetryError: Deadline of 60.0s exceeded while calling target function, last exception: 504 Deadline Exceeded

[chrisK824]

Hi @gkevinzheng , have you taken a look at the above maybe? Any suggestions?

[gkevinzheng]

@chrisK824 Sorry for the late reply. We will try to look at exposing the retries that are used under the hood.

[gkevinzheng]

@chrisK824 In the meantime you can look at switching from using setup_logging, which defaults to CloudLoggingHandler on App Engine, to manually setting up a StructuredLogHandler: https://cloud.google.com/python/docs/reference/logging/latest/std-lib-integration#manual-handler-configuration