Logging Interceptor unhandled exception and multiple logs of a single event
martinagrzybowska opened this issue · 0 comments
Describe the bug:
We are making requests to Google Ads API inside a Google Cloud Run. We have noticed quite some time ago that the default logging interceptor of this library seems to log one event (be a request being made to the Google Ads API, or an exception announcement) multiple times (hundreds of times, in fact). All these logs in Google Cloud Logger look exactly the same (have the same RequestID in textPayload) and are just microseconds apart in their timestamps. What is happening now is that Google Cloud seems to have started rejecting this magnitude of log writes, with the library throwing an exception (complete traceback can be found below). We were able to stop this exception from appearing completely by setting google.ads.googleads.client logger to WARNING level, but that is not the desired behaviour.
`"Traceback (most recent call last):
File "/app/ads_service/ads_client_handler.py", line 44, in inner
return wrapped_function(self)
File "/app/ads_service/search/search_service.py", line 18, in post
result = self.search_stream(
File "/app/ads_service/ads_client_handler.py", line 31, in inner
return wrapped_function(*args, **kwargs)
File "/app/ads_service/search/search_handler.py", line 19, in search_stream
result = self.search(customer_id, query, 10000, None)
File "/app/ads_service/search/search_handler.py", line 48, in search
response = service.search(request=request, retry=Retry(timeout=350))
File "/usr/local/lib/python3.9/site-packages/google/ads/googleads/v16/services/services/google_ads_service/client.py", line 4191, in search
response = rpc(
File "/usr/local/lib/python3.9/site-packages/google/api_core/gapic_v1/method.py", line 131, in call
return wrapped_func(*args, **kwargs)
File "/usr/local/lib/python3.9/site-packages/google/api_core/retry/retry_unary.py", line 293, in retry_wrapped_func
return retry_target(
File "/usr/local/lib/python3.9/site-packages/google/api_core/retry/retry_unary.py", line 153, in retry_target
_retry_error_helper(
File "/usr/local/lib/python3.9/site-packages/google/api_core/retry/retry_base.py", line 212, in retry_error_helper
raise final_exc from source_exc
File "/usr/local/lib/python3.9/site-packages/google/api_core/retry/retry_unary.py", line 144, in retry_target
result = target()
File "/usr/local/lib/python3.9/site-packages/google/api_core/grpc_helpers.py", line 76, in error_remapped_callable
return callable(*args, **kwargs)
File "/usr/local/lib/python3.9/site-packages/grpc/_interceptor.py", line 277, in call
response, ignored_call = self._with_call(
File "/usr/local/lib/python3.9/site-packages/grpc/_interceptor.py", line 332, in _with_call
return call.result(), call
File "/usr/local/lib/python3.9/site-packages/grpc/_interceptor.py", line 171, in result
raise self._exception
File "/usr/local/lib/python3.9/site-packages/grpc/_interceptor.py", line 315, in continuation
response, call = self._thunk(new_method).with_call(
File "/usr/local/lib/python3.9/site-packages/grpc/_interceptor.py", line 343, in with_call
return self._with_call(
File "/usr/local/lib/python3.9/site-packages/grpc/_interceptor.py", line 329, in _with_call
call = self._interceptor.intercept_unary_unary(
File "/usr/local/lib/python3.9/site-packages/google/ads/googleads/interceptors/logging_interceptor.py", line 338, in intercept_unary_unary
self.log_request(client_call_details, request, response)
File "/usr/local/lib/python3.9/site-packages/google/ads/googleads/interceptors/logging_interceptor.py", line 310, in log_request
self.log_successful_request(
File "/usr/local/lib/python3.9/site-packages/google/ads/googleads/interceptors/logging_interceptor.py", line 228, in log_successful_request
self.logger.info(
File "/usr/local/lib/python3.9/logging/init.py", line 1446, in info
self._log(INFO, msg, args, **kwargs)
File "/usr/local/lib/python3.9/logging/init.py", line 1589, in _log
self.handle(record)
File "/usr/local/lib/python3.9/logging/init.py", line 1599, in handle
self.callHandlers(record)
File "/usr/local/lib/python3.9/logging/init.py", line 1661, in callHandlers
hdlr.handle(record)
File "/usr/local/lib/python3.9/logging/init.py", line 952, in handle
self.emit(record)
File "/usr/local/lib/python3.9/site-packages/google/cloud/logging_v2/handlers/handlers.py", line 213, in emit
self.transport.send(
File "/usr/local/lib/python3.9/site-packages/google/cloud/logging_v2/handlers/transports/sync.py", line 56, in send
self.logger.log(
File "/usr/local/lib/python3.9/site-packages/google/cloud/logging_v2/logger.py", line 257, in log
self.log_text(message, client=client, **kw)
File "/usr/local/lib/python3.9/site-packages/google/cloud/logging_v2/logger.py", line 199, in log_text
self._do_log(client, TextEntry, text, **kw)
File "/usr/local/lib/python3.9/site-packages/google/cloud/logging_v2/logger.py", line 168, in _do_log
client.logging_api.write_entries(entries, partial_success=True)
File "/usr/local/lib/python3.9/site-packages/google/cloud/logging_v2/_http.py", line 191, in write_entries
self.api_request(method="POST", path="/entries:write", data=data)
File "/usr/local/lib/python3.9/site-packages/google/cloud/_http/init.py", line 494, in api_request
raise exceptions.from_http_response(response)
google.api_core.exceptions.BadGateway: 502 POST https://logging.googleapis.com/v2/entries:write?prettyPrint=false:
502. That’s an error.
The server encountered a temporary error and could not complete your request.
Please try again in 30 seconds. That’s all we know.`
Steps to Reproduce:
To reproduce the numerous logs of a single request being made to Google Ads API, simply make a request to the API :D The exception seems to be the direct of cause of these numerous requests being made a the same time.
Expected behavior:
A single event is only logged once. Or is there a reason why it is logged multiple times? As far as I can remember, this library has always been doing this, it is just now that this started causing an exceptions.
Client library version and API version:
Client library version: 24.0.0