Python-Celery Log

Question

I use flask, python 3.x and celery4 (Total 8 workers)

I want to make log files with 'RotatingFileHandler' to split if file size is over.

It works fine at first log file. (It includes all workers log, PoolWorker-1 ~ PoolWorker-8)

-rw-rw-r-- 1 sj sj   1048530  9월 18 10:01 celery_20170918.log (All worker's log)

But when file size is over, the worker write logs on seperated files.

-rw-rw-r-- 1 sj sj    223125  9월 18 10:47 celery_20170918.log  (All worker's log except below 2, 5, 6))
-rw-rw-r-- 1 sj sj     43785  9월 18 10:47 celery_20170918.log.1 (only PoolWorker-2 log)
-rw-rw-r-- 1 sj sj     46095  9월 18 10:47 celery_20170918.log.2 (only PoolWorker-5 log)
-rw-rw-r-- 1 sj sj     45990  9월 18 10:47 celery_20170918.log.3 (only PoolWorker-6 log)
-rw-rw-r-- 1 sj sj   1048530  9월 18 10:01 celery_20170918.log.4 (Log file made at first is changed to this.)

I don't know what is the rule and they have any duplicated logs..!!!

My celery logger is as below.

tasks.py

logger = get_task_logger('tasks')
logger.setLevel("INFO")
filename = './log/celery/celery_task.log'
formatter = Formatter('%(levelname)s-%(asctime)s %(processName)s %(funcName)s():%(lineno)d %(message)s')
# FileSize rotating
fileMaxByte = 1024 * 1024 * 1  # 30MB
fileHandler = logging.handlers.RotatingFileHandler(filename, maxBytes=fileMaxByte, backupCount=100)
fileHandler.setFormatter(formatter)
logger.addHandler(fileHandler)

@celery.task(...options...)
def test_call(self):
    logger.info("LOG TEST")

test.py

if __name__ == '__main__':
    test_call.apply_async()

What's wrong?

Answer 1

RotatingFileHandler don't maintain atomicity between multiprocess when do log file rollover.

In multi processes environment, process A see maxBytes reached on log file c.log, do a file rename to c.log.1, then write some log lines to newly created c.log.

But at the same time, another process B may still holding a handle of c.log, because the way used to check file size, is based on the end offset of file handle, it also sees maxBytes reached, want to do file roll over on its own, because the way used to roll over, is rename file on disk, this process try to rename c.log to c.log.1, but as c.log.1 exists, renamed to c.log.2.

As there are other processes, c.log.3 get created so on and so forth.

This issue is well addressed by using external logging mechanism, or you could wrap up your own atomic file rotating logging handler.