How to do clean logging, without making code look awful?

Question

I am trying to write clean code, so i don't want my code to be polluted with random logging. This for me looks awful:

def generate_auth_token(self):
    logger.debug("Existing auth token: {}".format(self.auth_token))
    self.auth_token = uuid.uuid4()
    self.save()
    logger.debug("Updated auth token:  {}".format(self.auth_token))
    return str(self.auth_token)

The logs then looks like this:

backend-api_1  | DEBUG: Device token: 66f4b515-c6f5-433c-885f-61c8a1f63ce5
backend-api_1  | Debug: Existing auth token: 66f4b515-c6f5-433c-885f-61c8a1f63ce5
backend-api_1  | Debug: Updated auth token: 66f4b515-c6f5-433c-885f-61c8a1f63ce5

It just difficult to read code like that. I came up with idea, to log every function, by using decorator.

def log_input_output(logger_name='', func_name=None, log_input_values=True):
  logger = logging.getLogger(logger_name)

  def _log_input_output_decorator(func):
    if not func_name:
      message_prefix = f'{func.__name__}'
    else:
      message_prefix = f'{func_name}'

    @wraps(func)
    def wrapper(*args, **kwargs):
      logger.info(f'{message_prefix} started')
      if log_input_values:
        if args:
          logger.debug(f'{message_prefix} input args: {args}')
        if kwargs:
          logger.debug(f'{message_prefix} input kwargs: {kwargs}')

      try:
        result = func(*args, **kwargs)
      except Exception as e:
        logger.error(f'{message_prefix} error: {e}')
        raise e

      logger.info(f'{message_prefix} finished successfully')
      logger.debug(f'{message_prefix} finished with result: {result}')
      return result

    return wrapper
  return _log_input_output_decorator

Example from above, now looks much more clean

  @log_input_output(logger_name=__name__)
  def generate_auth_token(self):
        self.auth_token = uuid.uuid4()
        self.save()
        return str(self.auth_token)

but the logs are, less clean

backend-api_1  | INFO: generate_auth_token started
backend-api_1  | DEBUG: generate_auth_token input args: (<self object at 0x7fc18085d1c8>)
backend-api_1  | INFO: generate_auth_token finished successfully
backend-api_1  | DEBUG: generate_auth_token finished with result: 66f4b515-c6f5-433c-885f-61c8a1f63ce5

In this case we are also missing the old token value. I just wonder, Is there like proper way of logging, so the code would not look like mess, but at the same time the logs would be more readable?

Answer 1

One possible solution is to add __repr__ to your class that will return what you want to log:

def __repr__(self):
    return str(self.auth_token)

This solution is not flexible because if you want to log self.auth_token in one function and self.other_attribute in other, you need to log them both everytime:

def __repr__(self):
    return str(self.auth_token, self.other_attribute)

It will mess your logs of def generate_auth_token(self): because you want to log only self.auth_token

Another solution I can propose is to use eval. I know that eval is evil, but maybe it is appropriate place to use it. Modifications to your code:

1) decorator will be used as follows:

@log_input_output(logger_name=__name__, log_eval='f"token is {self.auth_token}"')

2) parameter log_eval:

def log_input_output(logger_name='', func_name=None, log_input_values=True, log_eval=''):

3) if log_eval block placed after if kwargs:

    if kwargs:
      logger.debug(f'{message_prefix} input kwargs: {kwargs}')
    if log_eval:
      signature = inspect.signature(func)
      bind = signature.bind(*args, **kwargs)
      custom_log = eval(log_eval, bind.arguments)
      logger.debug(f'{message_prefix} custom log: {custom_log}')

So, the log will look like :

generate_auth_token custom log: token is d0173388-f043-4e8b-8630-05634e2fd3c6

With this solution you can log only self.other_attribute when other function is executed:

@log_input_output(logger_name=__name__, log_eval='f"other_attribute is {self.other_attribute}"')
def other_function(self):
    pass