googleads / google-ads-python

Google Ads API Client Library for Python
Apache License 2.0
526 stars 480 forks source link

Logging Interceptor unhandled exception and multiple logs of a single event #868

Open martinagrzybowska opened 5 months ago

martinagrzybowska commented 5 months ago

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_remappedcallable 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: <!DOCTYPE html>

Error 502 (Server Error)!!1

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