DEV Community: ddangdol

django LOGGING 의 disable_existing_loggers 동작 방식에 대한 이해

ddangdol — Wed, 12 May 2021 13:19:49 +0000

django logging

django는 python의 builtin 로깅 모듈을 사용하여 시스템 로깅 작업을 수행합니다. settings.py LOGGING을 통해 설정이 가능합니다. setting.py 에 LOGGING 설정이 없을 경우 아래 예시처럼 default 설정을 제공합니다.

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'filters': {
        'require_debug_false': {
            '()': 'django.utils.log.RequireDebugFalse',
        },
        'require_debug_true': {
            '()': 'django.utils.log.RequireDebugTrue',
        },
    },
    'formatters': {
        'django.server': {
            '()': 'django.utils.log.ServerFormatter',
            'format': '[{server_time}] {message}',
            'style': '{',
        }
    },
    'handlers': {
        'console': {
            'level': 'INFO',
            'filters': ['require_debug_true'],
            'class': 'logging.StreamHandler',
        },
        'django.server': {
            'level': 'INFO',
            'class': 'logging.StreamHandler',
            'formatter': 'django.server',
        },
        'mail_admins': {
            'level': 'ERROR',
            'filters': ['require_debug_false'],
            'class': 'django.utils.log.AdminEmailHandler'
        }
    },
    'loggers': {
        'django': {
            'handlers': ['console', 'mail_admins'],
            'level': 'INFO',
        },
        'django.server': {
            'handlers': ['django.server'],
            'level': 'INFO',
            'propagate': False,
        },
    }
}

위 설정을 간단히 설명하자면 django 와 django.server 두 개의 logger 를 기본으로 사용하도록 설정되어있습니다. django logger 의 경우 root 를 제외한 최상위 logger 이며 console handler 를 사용하게 되는데 debug=True 일 경우만 동작하도록 require_debug_true Filter 를 사용하고 있습니다.

django.server logger 는 django 의 요청처리와 관련된 로그 메시지를 기록하며 propagate 값이 False 이므로 상위 logger 인 django 에 전파되지 않습니다.

django logger 종류

django 는 여러 상황에 대한 로그메시지를 구분하고 기록하기 위해 기본적으로 아래 logger 들을 제공합니다. 자세한 내용은 Django logging extensions 문서를 통해 확인합니다. 여기서는 간단하게 설명합니다.

django

django framework 에서 로그 메시지를 기록하는데 직접적으로 사용되지는 않지만 아래 logger 들을 모두 포함하는 최상위 logger 입니다.

django.request

요청을 처리와 관련된 로그 메시지 입니다. 5XX 응답은 ERROR 레벨로 기록되며, 4XX 응답은 WARNING 레벨로 기록됩니다. django.security logger 에 기록되는 내용은 django.request 로거에 중복으로 기록되지 않습니다.

django.server

django runserver command 를 통해 구동되었을 경우 기록되는 logger 이며 요청 처리와 관련된 로그메시지를 기록합니다. 5XX 응답은 ERROR 레벨로 기록되며, 4XX 응답은 WARNING 레벨로 기록됩니다. 그 외 모든 로그메시지는 INFO 레벨로 기록됩니다.

django.template

django template 랜더링과 관련된 로그 메시지입니다.

django.db.backends

요청에 의해 실행되는 모든 애플리케이션 레벨의 SQL 문을 DEBUG 레벨로 기록합니다. 성능상의 이유로 설정된 logging 레벨과 관계없이 DEBUG=True 일 경우만 활성화됩니다.

django.security.*

보안관련 로그메시지를 기록합니다. 자세한 내용은 위 django 문서 링크를 확인합니다. 관련된 내용은 추후 자세히 다룰 예정입니다.

django.db.backends.schema

migration frmaework 에 의해 실행된 데이터베이스의 스키마 변경 SQL 쿼리들을 기록합니다.

diable_existing_loggers

disable_existing_loggers 값이 True 일 경우 해당 LOGGING 설정이 적용될 때 이미 존재하는 로거들을 비활성화 시키게 됩니다. True 로 설정한 경우 gunicorn 같은 WSGI 서버들의 logging 설정에 영향을 줄 수 있습니다. 예를 들어 아래 django LOGGING 설정을 사용한 app을 gunicorn 통해 실행한다고 가정해봅시다.

LOGGING = {
    'version': 1,
    'disable_existing_loggers': True, # 위 설정에서 해당 값만 True 로 변경
    'filters': {
        'require_debug_false': {
            '()': 'django.utils.log.RequireDebugFalse',
        },
        'require_debug_true': {
            '()': 'django.utils.log.RequireDebugTrue',
        },
    },
    'formatters': {
        'django.request': {
            '()': 'django.utils.log.ServerFormatter',
            'format': '[{server_time}] {message}',
            'style': '{',
        }
    },
    'handlers': {
        'console': {
            'level': 'INFO',
            'filters': ['require_debug_true'],
            'class': 'logging.StreamHandler',
        },
        'django.request': {
            'level': 'INFO',
            'class': 'logging.StreamHandler',
            'formatter': 'django.request',
        },
        'mail_admins': {
            'level': 'ERROR',
            'filters': ['require_debug_false'],
            'class': 'django.utils.log.AdminEmailHandler'
        }
    },
    'loggers': {
        'django': {
            'handlers': ['console', 'mail_admins'],
            'level': 'INFO',
        },
        'django.request': {
            'handlers': ['django.request'],
            'level': 'INFO',
            'propagate': False,
        },
    }
}

gunicorn logger

gunicorn 은 gunicorn.access, gunicorn.error 두 종류의 logger 를 사용합니다. gunicorn 은 master 와 worker process 로 구성됩니다. master process 는 worker 를 관리하는 역할을 하고 worker 가 실직적으로 django app 이 로드되는 process 입니다.

master 의 경우 gunicorn logging 설정을 그대로 사용하므로 로드메시지가 기록되는데 문제가 없습니다. worker 의 경우 위 최초에 gunicorn logging 설정을 적용한 후 django app 이 등록되는 타이밍에 django logging 설정이 적용됩니다. 이 때 django 관련 logger 는 활성화되나 gunicorn 의 gunicorn.access, gunicorn.error 로거가 disabled 되어 로그메시지가 기록되지 않는 상황이 발생합니다.

master process 는 django app 을 로드하지 않으므로 gunicorn.access, gunicorn.error 로그메시지가 기록됩니다.

결국 아래와 같이 worker 의 disabled 된 로거들이 존재하게 됩니다.

결론

대부분의 경우 disable_existing_loggers 값을 True 로 설정할 필요는 없으나 만약 필요한 경우 반드시 동작방식을 이해하고 사용하도록 합니다.

참고

python unittest 의 fixture scope

ddangdol — Wed, 14 Apr 2021 14:26:42 +0000

python testing tool

python 에는 널리 알려져 사용되는 여러 도구들이 이미 많습니다. 특히 pytest 는 좀 더 직관적인 assert 구문과 test 결과를 제공하며, 많은 plugin 을 보유하고 있습니다. 하지만 여러 도구들을 알아보기 전에 python testing에 기반이 되는 unittest 프레임워크의 개념과 사용법에 대해 알아보겠습니다.

오늘은 그 중 fixture의 종류와 사용범위에 대해 알아보겠습니다.

Test Fixture

테스트 픽스쳐는 테스트를 수행 시 필요한 리소스 준비과 이를 정리하는 동작에 해당합니다. unittest 프레임워크에서는 fixture를 여러 scope에서 사용할 수 있도록 기능을 제공합니다. 아래에서 Test, Class, Module Scope를 위한 fixture 사용법에 대해 알아보겠습니다.

Test Scope

TestCase 의 각 테스트에서 사용될 fixture의 준비와 정리는 setUp()과 tearDown()을 사용하게 됩니다. 테스트마다 반복될 수 있는 fixture를 setUp() 메소드와 tearDown() 메소드를 사용해 분리할 수 있습니다. 테스트 프레임워크가 각 테스트 실행 전후에 두 메소드를 자동으로 호출합니다.

import unittest


class RemainderTest(unittest.TestCase):
  def setUp(self) -> None:
    self.number = 2
    print('setUp')

  def tearDown(self) -> None:
    print('tearDown')

  def test_even(self):
    self.assertEqual(self.number % 2, 0)

  def test_odd(self):
    self.assertNotEqual(self.number % 2, 1)

위 테스트를 실행한 결과를 통해 각 테스트별로 매번 fixture가 생성되는 것을 알 수 있습니다.

setUp
tearDown
setUp
tearDown

setUp() 메소드 작업에서 예외가 발생하면 tearDown 메소드는 호출되지 않습니다.

class RemainderTest(unittest.TestCase):
    def setUp(self) -> None:
        self.number = 2
        print('setUp')
        raise Exception()

    def tearDown(self) -> None:
        print('tearDown')

    def test_even(self):
        self.assertEqual(self.number % 2, 0)

    def test_odd(self):
        self.assertNotEqual(self.number % 2, 1)

setUp
Error
Traceback (most recent call last):
...
setUp
Error
Traceback (most recent call last):
...

setUp 메소드 실행이 성공했다면 테스트 실패 여부과 관계없이 tearDown 메소드가 호출됩니다.

테스트 중에 사용된 자원을 정리하기 위해 tearDown 이후에 불리는 함수를 추가할 수 있습니다. 추가된 순서의 반대 순서(LIFO)로 불리게 됩니다. 함수가 추가될 때 addCleanup에 같이 전달된 위치 인자나 키워드 인자와 함께 호출됩니다.

def cleanUp():
    print('cleanUp')


class RemainderTest(unittest.TestCase):
    def setUp(self) -> None:
        self.number = 2
        print('setUp')
        self.addCleanup(cleanUp)

    def tearDown(self) -> None:
        print('tearDown')

    def test_even(self):
        self.assertEqual(self.number % 2, 0)

setUp
tearDown
cleanUp

또한 setUp 메소드에서 예외가 발생하면 tearDown 메소드가 호출되지 않아도 doCleanups 메소드가 실행됩니다.

def cleanUp():
    print('cleanUp')


class RemainderTest(unittest.TestCase):
    def setUp(self) -> None:
        self.number = 2
        print('setUp')
        self.addCleanup(cleanUp)
        raise Exception()

    def tearDown(self) -> None:
        print('tearDown')

    def test_even(self):
        self.assertEqual(self.number % 2, 0)

setUp
cleanUp

Error
Traceback (most recent call last):

doCleanUp 메소드를 직접 호출하여 addCleanUp에 추가된 함수들을 tearDown 호출 이전에 정리할 수도 있습니다.

def cleanUp():
    print('cleanUp')


class RemainderTest(unittest.TestCase):
    def setUp(self) -> None:
        self.number = 2
        print('setUp')
        self.addCleanup(cleanUp)

    def tearDown(self) -> None:
        print('tearDown')

    def test_even(self):
        self.assertEqual(self.number % 2, 0)
        self.doCleanups()

setUp
cleanUp
tearDown

Class Scope

Test Class 범위에 fixture는 unittest.TestSuite에 의해 관리되는 setUpClass와 tearDownClass가 있습니다. 해당 fixture는 Test Class의 모든 테스트와 공유되는 점을 주의해야 합니다. 아래와 같이 특정 테스트에서 str_list fixture의 수정이 일어나게 되면 이후 테스트에 영향을 미치게 됩니다.

class JoinTest(unittest.TestCase):
    @classmethod
    def setUpClass(cls) -> None:
        cls.str_list = ['foo', 'bar']
        print('setUpClass')

    @classmethod
    def tearDownClass(cls) -> None:
        print('tearDownClass')

    def test_join_with_colon(self):
        expected = 'foo:bar'
        self.assertEqual(':'.join(self.str_list), expected)
        self.str_list.append('baz')

    def test_join_with_comma(self):
        expected = 'foo,bar'
        self.assertEqual(','.join(self.str_list), expected)
        self.str_list.append('baz')

setUpClass 메소드 작업에서 예외가 발생하면 tearDownClass 메소드는 호출되지 않습니다.

test scope와 마찬가지로 cleanUp을 위한 addClassCleanup 메소드를 제공합니다. setUpClass 메소드에서 예외가 발생하면 tearDownClass 메소드가 호출되지 않아도 doClassCleanups 메소드가 실행됩니다.

def classCleanUp():
    print('classCleanUp')


class JoinTest(unittest.TestCase):
    @classmethod
    def setUpClass(cls) -> None:
        cls.str_list = ['foo', 'bar']
        print('setUpClass')
        cls.addClassCleanup(classCleanUp)

    @classmethod
    def tearDownClass(cls) -> None:
        print('tearDownClass')

    def test_join_with_colon(self):
        expected = 'foo:bar'
        self.assertEqual(':'.join(self.str_list), expected)

addClassCleanup에 추가된 함수들을 tearDownClass 이전에 정리하고 싶다면 doClassCleanups 메소드를 사용해 미리 정리할 수 있습니다.

Module Scope

module scope 에서는 setUpModule과 tearDownModule을 제공하며 함수로 작성되어야 합니다. 마찬가지로 setUpModule 실행 중 예외가 발생하면 tearDownModule 함수는 호출되지 않습니다.

def setUpModule():
    print('setUpModule')


def tearDownModule():
    print('tearDownModule')


class JoinTest(unittest.TestCase):
    def test_join_with_colon(self):
        expected = 'foo:bar'
        self.assertEqual(':'.join(['foo', 'bar']), expected)


class RemainderTest(unittest.TestCase):
    def test_even(self):
        self.assertEqual(2 % 2, 0)

setUpModule
tearDownModule

module scope에 cleanUp을 위해 unittest.addModuleCleanup 함수를 제공합니다. tearDownModule 함수가 호출된 이후 unittest.case.doModuleCleanups 함수를 통해 추가된 cleanUp 함수들이 호출됩니다.

def setUpModule():
    print('setUpModule')


def tearDownModule():
    print('tearDownModule')


def moduleCleanUp():
    print('moduleCleanUp')


class JoinTest(unittest.TestCase):
    def test_join_with_colon(self):
        expected = 'foo:bar'
        self.assertEqual(':'.join(['foo', 'bar']), expected)
        unittest.addModuleCleanup(moduleCleanUp)

setUpModule
tearDownModule
moduleCleanUp

tearDownModule이 호출되기 전에 추가된 정리 함수들을 호출하고 싶다면 unittest.case.doModuleCleanups 함수를 직접 호출합니다.

def setUpModule():
    print('setUpModule')


def tearDownModule():
    print('tearDownModule')


def moduleCleanUp():
    print('moduleCleanUp')


unittest.addModuleCleanup(moduleCleanUp)


class JoinTest(unittest.TestCase):
    def test_join_with_colon(self):
        expected = 'foo:bar'
        self.assertEqual(':'.join(['foo', 'bar']), expected)
        unittest.case.doModuleCleanups()


class RemainderTest(unittest.TestCase):
    def test_even(self):
        self.assertEqual(2 % 2, 0)

setUpModule
moduleCleanUp
tearDownModule

전체적인 fixture scope 흐름

def setUpModule():
    print('setUpModule')


def tearDownModule():
    print('tearDownModule')


def cleanUp():
    print('cleanUp')


def classCleanUp():
    print('classCleanUp')


def moduleCleanUp():
    print('moduleCleanUp')


unittest.addModuleCleanup(moduleCleanUp)


class JoinTest(unittest.TestCase):
    def setUp(self) -> None:
        print('setUp')
        self.addCleanup(cleanUp)

    def tearDown(self) -> None:
        print('tearDown')

    @classmethod
    def setUpClass(cls) -> None:
        print('setUpClass')
        cls.addClassCleanup(classCleanUp)

    @classmethod
    def tearDownClass(cls) -> None:
        print('tearDownClass')

    def test_join_with_colon(self):
        expected = 'foo:bar'
        self.assertEqual(':'.join(['foo', 'bar']), expected)

위에서 언급된 fixture scope 를 모두 포함한 결과를 보면 호출 순서는 아래와 같습니다.

setUpModule
setUpClass
setUp
tearDown
cleanUp
tearDownClass
classCleanUp
tearDownModule
moduleCleanUp

정리

python unittest를 사용해 테스트 작성 시 fixture 별 scope와 호출 시점과 조건을 잘 파악해야 합니다. 여러 scope의 fixture를 잘 활용하면 중복을 해결하고 테스트 성능에 도움이 되지만 잘못 사용할 경우 의도와 다른 테스트 결과가 출력될 수 있음에 주의하며 사용하는 것이 좋습니다.

참고

https://docs.python.org/ko/3/library/unittest.html