burnash
logging for requests and retries
I recently had an issue trying to update a large Google Sheet, where the request was hanging indefinitely. This was difficult to diagnose because there is no visibility into the requests gspread is making. I needed to distinguish between
- hanging indefinitely because by default there is no timeout
- timing out
- retrying / waiting between retries
I want to be able to see when a request
- is started
- completes successfully
- fails, and why
- is retried
I did not see logging that I could enable, or any way to extend the clients to add my own logging. For now, I have copied the contents of BackOffHTTPClient into my own class and added logging. I'd prefer to use the the official BackOffHTTPClient, with hooks to add my own logging.
I'd like to propose a pull request that adds functions to HTTPClient and BackOffHTTPClient that allow adding additional behavior while maintaining core functionality. For example, I'd like to add something like this to HTTPClient / BackOffHTTPClient
def on_request_start(self, *args: Any, **kwargs: Any) -> None:
pass
def on_request_complete(self, *args: Any, **kwargs: Any) -> None:
pass
def on_request_fail(self, *args: Any, **kwargs: Any) -> None:
pass
def on_request_retry(self, *args: Any, **kwargs: Any) -> None:
pass
In my class, I'd override these methods to add structured logging:
def on_start_request(self, *args: Any, **kwargs: Any) -> None:
self.request_start = datetime.now()
log.info(f"gspread: request started for {args}")
def on_request_fail(self, *args: Any, **kwargs: Any) -> None:
elapsed = (datetime.now() - self.request_start).total_seconds()
error = kwargs.get("error", "unknown")
log.info(
f"gspread: request failed with {error} in {elapsed} seconds for {args}",
extra={"elapsed": elapsed, "code": kwargs.get("code"), "error": error},
)
Related but could be addressed in a separate PR:
The BackOffHTTPClient handles APIErrors, but not timeouts. In my custom class, I added ReadTimeout to the except clause, so that requests that timed out could be retried.
Hello...I was working with @kielni on this issue, and if I might suggest an approach, it would be to use before and after hooks, something like this.
def hookable(method):
def wrapper(self, *args, **kwargs):
self._run_hooks(self.before_hooks, method.__name__, args, kwargs)
result = method(self, *args, **kwargs)
self._run_hooks(self.after_hooks, method.__name__, args, kwargs, result)
return result
return wrapper
class MyService(Hookable):
@hookable
def do_work(self, data):
return data.upper()
I'm going to poke around a little with this and see if I can submit a PR for it
@alifee et al. -- I submitted https://github.com/burnash/gspread/pull/1567 for consideration. Love the gspread library, and thanks for looking it over!
