Extra logging handler

[tesence]

I'm using gspread_asyncio 1.9.0 (with gspread 5.10.0) and I've been noticing a weird logging behaviour.

Whenever AsyncioGspreadClient.open() is called, an extra handler is added to the one I'm configure in my code, dupplicating any log output

Small example that works as expected with vanilla gspread 5.10.0

import logging

import gspread
from google.oauth2.service_account import Credentials

def main():
    
    steam_handler = logging.StreamHandler()
    logger = logging.getLogger("test")
    logger.setLevel(logging.INFO)
    logger.addHandler(steam_handler)
    
    creds = Credentials.from_service_account_file(
        "service_account.json",
        scopes = [
            "https://spreadsheets.google.com/feeds",
            "https://www.googleapis.com/auth/spreadsheets",
            "https://www.googleapis.com/auth/drive",
        ]
    )
    client = gspread.authorize(creds)
    logger.info("Before client.open")
    spreadsheet = client.open(title="My Spreadsheet")
    logger.info('After client.open')

if __name__ == "__main__":
    main()

Output

Before client.open
After client.open

The same example with gspread_asyncio 1.9.0 (relying on gspread 5.10.0)

import asyncio

import logging

import gspread_asyncio
from google.oauth2.service_account import Credentials

async def main():
    
    steam_handler = logging.StreamHandler()
    logger = logging.getLogger("test")
    logger.setLevel(logging.INFO)
    logger.addHandler(steam_handler)

    def get_creds():
        creds = Credentials.from_service_account_file("service_account.json")
        scoped = creds.with_scopes([
            "https://spreadsheets.google.com/feeds",
            "https://www.googleapis.com/auth/spreadsheets",
            "https://www.googleapis.com/auth/drive",
        ])
        return scoped

    agcm = gspread_asyncio.AsyncioGspreadClientManager(get_creds)
    
    agc = await agcm.authorize()
    
    logger.info("Before agc.open")
    spreadsheet = await agc.open(title="My Spreadsheet")
    logger.info('After agc.open')

if __name__ == "__main__":
    asyncio.run(main())

Output

Before agc.open
After agc.open
INFO:test:After agc.open

[dgilman]

The way the library did logging made sense when I put the thing together but may not be the best way to do it today. I apologize if this is a huge inconvenience for you, if I had the time I'd redo it but right now it's not worth messing with.

To answer your question, though: the library calls the module-level logging.debug, logging.error methods as part of its operation. It does not create its own logger (e.g. logger = logging.getLogger(__name__) like you might expect. This could be the cause of your problems.

To get around this, if you subclass AsyncioGspreadClientManager you can re-implement before_gspread_call, handle_gspread_error and handle_requests_error to do what you need it to do w/r/t logging. The original implementations are 1-2 lines long so it's hopefully not a huge lift.

I am not sure what your goals are with logging but maybe it could be something like this, or you could pass a logger instance in directly:

class MyAsyncioGspreadClientManager(AsyncioGspreadClientManager):
    def __init__(self, *args, **kwargs):
        self.logger = logging.getLogger(kwargs.pop("logger_name"))
        super().__init__(*args, **kwargs)

    async def before_gspread_call(self, method, args, kwargs):
        self.logger.debug(
            "Calling {0} {1} {2}".format(method.__name__, str(args), str(kwargs))
        )

    async def handle_gspread_error(self, e, method, args, kwargs):
        self.logger.error(
            "Error while calling {0} {1} {2}. Sleeping for {3} seconds.".format(
                method.__name__, str(args), str(kwargs), self.gspread_delay
            )
        )
        # Wait a little bit just to keep from pounding Google
        await asyncio.sleep(self.gspread_delay)

    async def handle_requests_error(self, e, method, args, kwargs):
        # By default, retry forever.
        self.logger.error(
            "Error while calling {0} {1} {2}. Sleeping for {3} seconds.".format(
                method.__name__, str(args), str(kwargs), self.gspread_delay
            )
        )
        # Wait a little bit just to keep from pounding Google
        await asyncio.sleep(self.gspread_delay)