mercredi 29 avril 2020

Python Logging patterns and BKMs

I often find myself adding lots of log prints to my code, either to assist with profiling and debugging or to inform users of issues with the tool they are running.

With this, I'm also finding that I'll have redundant logs printing, each with their own contexts. For example, suppose I had two functions:

def sub_function(args):
    logging.info(f"Beginning to look for things that match args: {args}")
    found_arguments = []
    for arg in args:
        logging.info(f"Searching file system for {arg}")
        ...
        if some_value:
            found_arguments.append(some_value)
            logging.info(f"Found value {some_value}!")

    logging.info(f"Found arguments: {found_arguments}")
    return found_arguments

def calling_function(args):
    logging.info(f"Going to search for {args}!")
    result = sub_function(args)
    logging.info("Found arguments: {result}")
    ...

This might produce a log that looks like:

Going to search for ["arg1", "arg2"]!
Beginning to look for things that match args: ["arg1", "arg2"]
Searching file system for "arg1"
Searching file system for "arg2"
Found value /tmp/arg2!
Found arguments: ["/tmp/arg2"]
Found arguments: ["/tmp/arg2"]

Barring the fact that this example will produce a lot of logging output, it doesn't have a way to separate context for the logging. For example, a developer might be very interested to know what is happening in the sub_function() and doesn't necessarily care what tools or outer calling_function()s might be utilizing it.

But a tool developer wants to produce specific messages for the results, and doesn't necessarily care about the internal workings of the sub_function(), just that they have their calling_function() and need to print specific messages. Users might get frustrated, or even ignore logging if there is too much 'junk' in the log.

Is there a best practice for how to handle logging in this way? Of course, I could change some logs to logging.debug() instead of logging.info() but that requires a lot of coordination between developers on different layers. One man's info is another man's debug, after all. The only thing I can think of is implementing different loggers, but then I can see that exploding into a multitude of different loggers that need to be able to redirect output to various places, which then could make it hard for developers and users to know exactly what they are gonna see when they run a tool.

Thanks

Aucun commentaire:

Enregistrer un commentaire