How to correctly make an assertLogs test with unittest using a django settings configuration for logging?

Question

I have a setting for logging in my django project and I want to make a test using assertLogs.

I used the example provided in the documentation: https://docs.python.org/3/library/unittest.html#unittest.TestCase.assertLogs

with self.assertLogs('foo', level='INFO') as cm:
   logging.getLogger('foo').info('first message')
   logging.getLogger('foo.bar').error('second message')
self.assertEqual(cm.output, ['INFO:foo:first message',
                             'ERROR:foo.bar:second message'])

My django settings are like below:

LOGGING = {
    'version': 1,
    'disable_existing_loggers': True,
    'formatters': {
        'verbose': {
            'format': '%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s'
        },
        'simple': {
            'format': '%(levelname)s %(message)s'
        },
        'standard': {
            'format': '%(asctime)s %(levelname)s %(name)s %(message)s'
        },
    },
    'filters': {
        'require_debug_true': {
            '()': 'django.utils.log.RequireDebugTrue',
        },
    },
    'handlers': {
        'console': {
            'level': 'INFO',
            'filters': ['require_debug_true'],
            'class': 'logging.StreamHandler',
        },
        'default': {
            'level':'DEBUG',
            'class':'logging.handlers.RotatingFileHandler',
            'filename': BASE_DIR + '/logs/default.log',
            'maxBytes': 1024*1024*5, # 5 MB
            'backupCount': 5,
            'formatter':'standard',
        },
        'debug_file': {
            'level':'DEBUG',
            'class':'logging.handlers.RotatingFileHandler',
            'filename': BASE_DIR + '/logs/debug.log',
            'maxBytes': 1024*1024*5, # 5 MB
            'backupCount': 5,
            'formatter':'standard',
        },
        'warning_file': {
            'level':'WARNING',
            'class':'logging.handlers.RotatingFileHandler',
            'filename': BASE_DIR + '/logs/warning.log',
            'maxBytes': 1024*1024*5, # 5 MB
            'backupCount': 5,
            'formatter':'standard',
        },
        'info_file': {
            'level':'INFO',
            'class':'logging.handlers.RotatingFileHandler',
            'filename': BASE_DIR + '/logs/info.log',
            'maxBytes': 1024*1024*5, # 5 MB
            'backupCount': 5,
            'formatter':'standard',
        },
        'error_file': {
            'level':'ERROR',
            'class':'logging.handlers.RotatingFileHandler',
            'filename': BASE_DIR + '/logs/error.log',
            'maxBytes': 1024*1024*5, # 5 MB
            'backupCount': 5,
            'formatter':'standard',
        },
        'mail_admins': {
            'level': 'ERROR',
            'class': 'django.utils.log.AdminEmailHandler',
        },
        'emails': {
            'level':'DEBUG',
            'class':'logging.handlers.RotatingFileHandler',
            'filename': BASE_DIR + '/logs/emails.log',
            'maxBytes': 1024*1024*5, # 5 MB
            'backupCount': 5,
            'formatter':'standard',
        },
    },
    'loggers': {
        'django': {
            'handlers': ['console'],
            'level': 'INFO',
        },
        'debug_logger': {
            'handlers': ['debug_file'],
            'level': 'DEBUG',
            'propagate': True
        },
        'info_logger': {
            'handlers': ['info_file'],
            'level': 'INFO',
            'propagate': True
        },
        'error_logger': {
            'handlers': ['error_file'],
            'level': 'ERROR',
            'propagate': True
        },
        'django.request': {
            'handlers': ['default', 'mail_admins'],
            'level': 'ERROR',
            'propagate': False,
        },
        'emails': {
            'handlers': ['emails'],
            'level': 'DEBUG',
            'propagate': True
        },

    }
}

And my test:

from django.test import TestCase
import unittest
import logging

class LoggerTestCase(unittest.TestCase):
    def test_message_logger(self):
        with self.assertLogs('loggers', level='INFO') as logs:
            logging.getLogger('debug_logger').debug('debug message')
            logging.getLogger('info_logger').info('info message')
            logging.getLogger('warning_logger').warning('warning message')
            logging.getLogger('error_logger').error('error message')
            logging.getLogger('critical_logger').critical('critical message')
        self.assertEqual(logs.output, ['INFO:loggers.debug:debug message', 
            'ERROR:loggers.info:info message', 
            'WARNING:loggers.warning:warning message', 
            'ERROR:loggers.error:error message', 
            'CRITICAL:loggers.critical:critical message'
            ])

But I'm getting this error:

Traceback (most recent call last):
line 16, in test_message_logger
    logging.getLogger('critical_logger').critical('critical message')
AssertionError: no logs of level INFO or higher triggered on loggers

I expect to use correctly the assertLogs. I already used my prints messages in my views and it worked fine, so how can i fix this error? I can't detect where is my mistake

Any help will be apreciate

Update

Replacing loggers by critical_loggerI get this error:

Traceback (most recent call last):
  File 
 line 19, in test_message_logger
    'CRITICAL:loggers.critical:critical message'
AssertionError: Lists differ: ['CRITICAL:critical_logger:critical message'] != ['INFO:loggers.debug:debug message', 'ERROR[149 chars]age']

Chlo

Answer 1

The first argument to assertLogs is the logger to which you expect the logging to happen. You don't have any logger using the loggers namespace - this is why it isn't working.

logging.getLogger('critical_logger').critical('critical message')

Here, the logger that you are using is critical_logger. In order to work, your assertion would have to be:

self.assertLogs('critical_logger', level='INFO')

I think the confusion is in the way you are logging in the first place - it doesn't make sense to use a different logger for each line in your test (debug_logger, info_logger etc). You need to use one logger, and your test assertion needs to look for logs in that one logger.

Licking

replacing loggers by critical_logger I get a different error, but I can understand what you're meaning, make a general assertLogs with only one logger it would be good, How could do that? – Chlo

Answer 2

For anyone else stumbling upon this, here's an example of what worked for me (based on this site). The thing I was misunderstanding from the docs was that the code being tested should be run inside the 'with' statement.

def test_logging(self):
    with self.assertLogs('<class_under_test logger name>', level='DEBUG') as logger:
        <run your code here>
        self.assertEqual(['DEBUG:<class_under_test logger name>:<expected output>'], logger.output)

As far as I can tell it doesn't matter if the assertEqual statement is inside or outside of the 'with' portion.

You can ascertain the class_under_test logger name through debugging, or running a print on the logger itself.

--Project structure--
src
  -class_under_test

--Code--
logger = logging.getLogger(__name__)
print(logger)

--output--
<Logger src.class_under_test (WARNING)>

So my full example would be:

def test_logging(self):
    with self.assertLogs('src.class_under_test', level='DEBUG') as logger:
        src.class_under_test.method1()
        self.assertEqual(['DEBUG:src.class_under_test:Method1 complete'], logger.output)

Even though the out put shows WARNING, I'm setting the log level of my 'with' statement to DEBUG, which isn't a problem.

Nolly