Logging with decorators (passing log file name as argument)

Question

This is for some quantum mechanics software so there will be references to molecules/atoms etc but the core issue is a python logging one, unrelated to all that.

I have a couple of logging decorators, one for logging what the program is doing, another to log exceptions (along with their full stack trace and some class object details to help with debugging).

To save me decorating every single method, I also have a class decorator which just applies a decorator to all methods of a class. This is:

def for_all_methods(decorator):
    """
    Applies a decorator to all methods of a class (includes sub-classes and init; it is literally all callables).
    This class decorator is applied using '@for_all_methods(timer_func)' for example.
    """

    @wraps(decorator)
    def decorate(cls):
        # Examine all class attributes.
        for attr in cls.__dict__:
            # Check if each class attribute is a callable method.
            if callable(getattr(cls, attr)):
                # Set the callables to be decorated.
                setattr(cls, attr, decorator(getattr(cls, attr)))
        return cls
    return decorate

The logging decorators are similar, the following is used to log method timings, while also giving the docstring, qualname and some other info:

def log_dec_factory(file_name):
    """
    Logs the various timings of a function in a dated and numbered file.
    Writes the start time, function / method qualname and docstring when function / method starts.
    Then outputs the runtime and time when function / method finishes.
    """
    def timer_logger(orig_func):

        @wraps(orig_func)
        def wrapper(*args, **kwargs):

            start_time = datetime.now().strftime('%Y-%m-%d %H:%M:%S')
            t1 = time()

            with open(file_name, 'a+') as log_file:
                log_file.write(f'{orig_func.__qualname__} began at {start_time}.\n\n')
                log_file.write(f'Docstring for {orig_func.__qualname__}:\n     {orig_func.__doc__}\n\n')

                time_taken = time() - t1

                mins, secs = divmod(time_taken, 60)
                hours, mins = divmod(mins, 60)

                secs, remain = str(float(secs)).split('.')

                time_taken = f'{int(hours):02d}h:{int(mins):02d}m:{int(secs):02d}s.{remain[:5]}'
                end_time = datetime.now().strftime('%Y-%m-%d %H:%M:%S')

                log_file.write(f'{orig_func.__qualname__} finished in {time_taken} at {end_time}.\n\n')
                # Add some separation space between function / method logs.
                log_file.write(f'{"-" * 50}\n\n')

            return orig_func(*args, **kwargs)
        return wrapper
    return timer_logger

So, when I want to get some log info for a particular method of a class, I decorate the class with for_all_methods() which takes the function / method decorator as an argument. The function / method decorator then takes the argument of the log file name, like so:

@for_all_methods(log_dec_factory('log_file.txt'))
class Engine:

    def __init__(self, molecule):

        self.molecule = molecule
        self.name = molecule.name
        self.log_file = molecule.log_file

    def print_name_to_terminal(self):
        print(self.name)
    ...

So now, whenever a method from the class Engine is invoked, the details of the invocation will be written to log_file.txt. Great!

To be clear, the molecule argument is a class which is getting passed around and stores all important information (atoms, coordinates, etc).

This is completely fine, except rather than providing a string for the log file name, I just want to get that from the molecule argument. In other words, I want to pass self.log_file into the decorator.

Now, I can do this with a quick and dirty global in the undecorated base class:

class Engine:

    def __init__(self, molecule):

        self.molecule = molecule
        self.name = molecule.name
        self.log_file = molecule.log_file
        log_file = self.log_file
        global log_file
    ...

@for_all_methods(log_dec_factory(log_file))
class PSI4(Engine):

    def __init__(self, molecule):

        super().__init__(molecule)
    ...

Now, this works but, it feels like a hacky workaround. (I've literally never needed to use a global in Python, there's always been a better / proper way.) This also only works if I have a base class which I don't want to log the methods for. Otherwise I have to go back to manually putting in the log file name.

So finally, my question is, is there a proper way of doing something like this? I use the logging module for my exception logger decorator but couldn't find what I wanted for this particular use case.

Many thanks in advance and apologies for the rather long post.

Answer 1

I'm not certain how you even got this to work. The decoration of the class occurs when the class is declared, not when an instance of the class is created, so setting of log_file will not have happened by the Engine constructor. You must have also declared the log_file elsewhere, and that is what is being used to decorate the class methods.

If I understand what you want to do properly, you will have multiple molecule instances, which each have their own log_file. During a PSI4 method, you want the logger (which was used to decorate the class) to reach into the instance's data, retrieving the molecule, and use the molecule's log_file.

Fortunately, the instance is passed as the first argument self to the wrapped method. You can use that to retrieve self.molecule, from which self.molecule.log_file can be found. Except the first argument is not always self (static and class methods), and self.molecule doesn't exist until partway through the constructor's execution. So the method decorator better check if the first argument exists, and whether it has a molecule member.

from functools import wraps

def all_methods(decorator):
    @wraps(decorator)
    def decorate(cls):
        for attr in cls.__dict__:
            if callable(getattr(cls, attr)):
                setattr(cls, attr, decorator(getattr(cls, attr)))
        return cls
    return decorate

def method_logger(method):
    @wraps(method)
    def wrapper(*args, **kwargs):
        log_file = 'nowhere'
        if len(args) >= 1 and hasattr(args[0], 'molecule'):
        #if len(args) >= 1 and isinstance(args[0], PSI4):
            log_file = args[0].molecule.log_file
        print(f"Logging {method.__name__}(...) to {log_file}")
        return method(*args, **kwargs)
    return wrapper

class Molecule:
    def __init__(self, log_file):
        self.log_file = log_file

@all_methods(method_logger)
class PSI4:
    def __init__(self, molecule):
        self.molecule = molecule

    def f(self): pass
    def g(self): pass

    @staticmethod
    def sm(): pass

    @classmethod
    def cm(cls): pass

e1 = PSI4(Molecule('file1'))
e2 = PSI4(Molecule('file2'))

e1.f()
e2.g()
PSI4.sm()
PSI4.cm()

Output:

Logging __init__(...) to nowhere
Logging __init__(...) to nowhere
Logging f(...) to file1
Logging g(...) to file2
Logging sm(...) to nowhere
Logging cm(...) to nowhere

Instead of checking for hasattr(args[0], 'molecule'), I'd love to use isinstance(args[0], PSI4), but args[0] is a PSI4 instance during the PSI4.__init__() call, but since the constructor hasn't run yet, self.molecule is still unassigned, even though the type of the instance is correct.