[Python] 멀티프로세싱 환경에서의 logging doRollOver() Error 32 해결법

Python TimedRotatingFileHandler.doRollOver() Error 32 문제

 Python의 logging 모듈에서 기본적으로 제공하는 TimedRotatingFileHandler를 사용하는 도중, 아래와 같은 에러가 발생했다.

https://stackoverflow.com/questions/29220435/windowserror-using-rotatingfilehandler-and-subprocess-popen

Traceback (most recent call last):

  File "c:\Python27\lib\logging\handlers.py", line 77, in emit

self.doRollover()

  File "c:\Python27\lib\logging\handlers.py", line 142, in doRollover

    os.rename(self.baseFilename, dfn)

WindowsError: [Error 32] The process cannot access the file because it is being used by another process

 doRollOver는 TimedRotatingFileHandler에 지정한 기간이 지났을 경우 사용하던 파일을 백업하고 새로운 로그 파일을 생성하도록 하는 함수이다. Error 32는 다른 프로세스나 스레드에서 같은 파일의 핸들러를 가지고 있기 때문에 변경이 불가능할 때 발생하는 에러이다. 당시 Multiprocessing 환경에서 사용중이었기 때문에 이것이 문제인가 싶어서 프로세스별로 다른 Logger를 사용하도록 변경해 보았으나 그래도 마찬가지로 발생하였고, 이를 해결하려고 수없이 돌아다녔다.

=== [2019-04-03] 업데이트

한동안 발생하지 않아서 방심하고 있었는데 여전히 버그는 발생했다. Error 32가 뜻하는 바도 그렇고 분명 뭔가 멀티프로세스 환경에서 다른 프로세스가 핸들을 물고 있어서 Rotating이 되지 않는 것이 분명했으므로 이를 확인하기 위해 테스트 코드를 짜 봤다.

import os
import time
import logging
import logging.handlers
import multiprocessing
 
def GetParentDirectory(filePath):
    return os.path.sep.join(filePath.split(os.path.sep)[:-1])
 
def Mkdirs(dirPath):
    if not os.path.exists(dirPath):
        os.makedirs(dirPath)
 
def CreateLogger(loggerName):
    # Create Logger
    logger = logging.getLogger(loggerName)
    if len(logger.handlers) > 0:
        return logger
 
    logger.setLevel(logging.DEBUG)
    formatter = logging.Formatter('\n[%(levelname)s|%(name)s|%(filename)s:%(lineno)s] %(asctime)s > %(message)s')
 
    # Create Handlers
    logPath = os.path.join(os.path.realpath(""), "logs", loggerName + ".log")
    Mkdirs(GetParentDirectory(logPath))
    streamHandler = logging.StreamHandler()
    streamHandler.setLevel(logging.DEBUG)
    streamHandler.setFormatter(formatter)
    rotatingHandler = logging.handlers.TimedRotatingFileHandler(logPath, when='M', backupCount=10)
    rotatingHandler.setLevel(logging.DEBUG)
    rotatingHandler.setFormatter(formatter)
 
    # Add handlers to logger
    logger.addHandler(streamHandler)
    logger.addHandler(rotatingHandler)
    return logger
 
def LoggingTest(pid):
    subLogger = CreateLogger("Process_%d" % (pid))
    count = 0
    while True:
        subLogger.info("Log : 0x%08x" % count)
        time.sleep(5)
        count += 1
 
def main():
    PROC_COUNT = 10
    mainLogger = CreateLogger("Main-Process")
 
    mainLogger.info("Start Creating Process")
    procList = []
    for i in range(PROC_COUNT):
        procList.append(multiprocessing.Process(target=LoggingTest, args=(i,)))
        procList[i].start()
        time.sleep(0.5)
    mainLogger.info("End Creating Process")
 
    count = 0
    while True:
        mainLogger.info("Main-Log : 0x%08x" % count)
        time.sleep(5)
        count += 1
 
if __name__ == '__main__':
    main()

 1분마다 Rotating하도록 설정하여 돌려봤는데, 아니나다를까 Main-Process 로거에서 doRollOver 에러가 발생한다. multiprocessing.Process로 생성한 자식 프로세스에서 main의 mainLogger 핸들러를 물고 있는 것이 아닌가 하는데... 

 돌려놓고 Rotating이 발생하기 전에 Process Hacker를 이용해 파일 핸들러를 찍어본 모습이다. Main과 Sub 모두 자신의 핸들러를 가지고 있는데, Sub에서 Main의 핸들러를 물고 있는 것을 볼 수 있다.

 doRollOver Error32가 발생한 이후 찍은 모습이다. Main에서는 Rotating을 위해 핸들러를 닫았지만 Sub에서는 계속 물고 있는 것을 볼 수 있다. 이래서 Error32가 발생한 것으로 파악할 수 있었다. 문제는 이걸 어떻게 해결하냐는 것인데... 파이썬 logging 라이브러리 자체가 멀티 프로세싱 환경을 고려하지 않고 만들어졌기 때문에 발생한 일이라 간단하게 해결하긴 힘들어 보인다. 여기(https://docs.python.org/ko/3/howto/logging-cookbook.html)에서는 소켓에 로그를 작성하고 이를 읽어서 기록하는 스레드를 따로 만들어 두고 돌리는 방식으로 처리가 가능함을 설명하고 있으며 실제로 multilog(https://pypi.org/project/multilog/)라고 하는 모듈이 이미 존재한다. 어느 쪽이든 로깅 모듈이 쓰이던 곳이 한두군데가 아니었기 때문에 고치기는 힘들겠지만 최대한 노력해 봐야겠다 (._.

 Windows 환경 해결법

import os
import time
import platform
import logging
import logging.handlers
import multiprocessing
 
def GetParentDirectory(filePath):
    return os.path.sep.join(filePath.split(os.path.sep)[:-1])
 
def Mkdirs(dirPath):
    if not os.path.exists(dirPath):
        os.makedirs(dirPath)
 
def CreateLogger(loggerName):
    # Create Logger
    logger = logging.getLogger(loggerName)
    if len(logger.handlers) > 0:
        print "Already Exists : %s" % (loggerName)
        return logger
    print "Non-Exists : %s" % (loggerName)
    logger.setLevel(logging.DEBUG)
    formatter = logging.Formatter('\n[%(levelname)s|%(name)s|%(filename)s:%(lineno)s] %(asctime)s > %(message)s')
 
    # Create Handlers
    logPath = os.path.join(os.path.realpath(""), "logs", loggerName + ".log")
    Mkdirs(GetParentDirectory(logPath))
    streamHandler = logging.StreamHandler() 
    streamHandler.setLevel(logging.DEBUG)
    streamHandler.setFormatter(formatter)
    rotatingHandler = logging.handlers.TimedRotatingFileHandler(logPath, when='M', backupCount=10)
    rotatingHandler.setLevel(logging.DEBUG)
    rotatingHandler.setFormatter(formatter)
    if platform.system() == 'Windows':
        import msvcrt
        import win32api
        import win32con
        win32api.SetHandleInformation(msvcrt.get_osfhandle(rotatingHandler.stream.fileno()), win32con.HANDLE_FLAG_INHERIT, 0)
 
    # Add handlers to logger
    logger.addHandler(streamHandler)
    logger.addHandler(rotatingHandler)
    
    return logger
 
def LoggingTest(pid):
    subLogger = CreateLogger("Process_%d" % (pid))
    count = 0
    while True:
        subLogger.info("Log : 0x%08x" % count)
        time.sleep(5)
        count += 1
 
def main():
    PROC_COUNT = 10
    mainLogger = CreateLogger("Main-Process")
 
    mainLogger.info("Start Creating Process")
    procList = []
    for i in range(PROC_COUNT):
        procList.append(multiprocessing.Process(target=LoggingTest, args=(i,)))
        procList[i].start()
        time.sleep(0.5)
    mainLogger.info("End Creating Process")
 
    count = 0
    while True:
        mainLogger.info("Main-Log : 0x%08x" % count)
        time.sleep(5)
        count += 1
 
if __name__ == '__main__':
    main()

CreateLogger 함수 내부, TimedRotatingFileHandler를 생성하는 부분 밑에 다음의 코드가 추가되었다.

    if platform.system() == 'Windows':
        import msvcrt
        import win32api
        import win32con
        win32api.SetHandleInformation(msvcrt.get_osfhandle(rotatingHandler.stream.fileno()), win32con.HANDLE_FLAG_INHERIT, 0)

파이썬 2.7~3.4에서는 multiprocessing으로 프로세스를 생성했을 때, 자식 프로세스가 부모 프로세스의 핸들러들을 상속받아서 같이 물고 있기 때문에 위와 같은 버그가 발생했었는데, 핸들러의 File Handle을 직접 받아와서 SetHandleInformation API를 사용해 상속하지 않도록 설정해주면 자식 프로세스가 생성될때 받아가지 않는다. (참고 : https://stackoverflow.com/questions/948119/preventing-file-handle-inheritance-in-multiprocessing-lib)