Add extra data to python log message

Til
Page content

TL;DR

  • QueueHandler를 사용해서 process-safe logger를 만들고
  • LoggerAdapter를 활용해서 매 로그 메시지마다 특정 정보가 자동으로 출력.

main.py

#!/usr/bin/env python3

import logging
import logging.handlers
import multiprocessing

from worker import worker_process
from my_logger import logger_process

if __name__ == "__main__":
    # Configure logging
    logging.basicConfig(level=logging.DEBUG)

    # Create a queue for logging
    log_queue = multiprocessing.Queue()

    # Create worker processes
    num_workers = 2
    processes = []
    for i in range(num_workers):
        p = multiprocessing.Process(target=worker_process, args=(i, log_queue))
        processes.append(p)
        p.start()

    # Create a logger process for process-safe loggging
    p = multiprocessing.Process(target=logger_process, args=(log_queue,))
    processes.append(p)
    p.start()

    # Wait for all processes to finish
    try:
        for p in processes:
            p.join()
    except KeyboardInterrupt:
        print("Uset interrupt. Stop")

worker.py

logger를 직접 사용하는 대신 LoggerAdapter를 사용해서 각 process의 추가 정보를 함께 출력.

#!/usr/bin/env python3

import time
import logging
from my_logger import WorkerAdapter

def worker_process(worker_index, log_queue):
    # Configure logger for the worker process

    worker_logger = logging.getLogger("main-logger")
    worker_logger.addHandler(logging.handlers.QueueHandler(log_queue))
    worker_logger.setLevel(logging.DEBUG)

    adapter = WorkerAdapter(worker_logger, {'worker_index': worker_index})
    count = 0

    print(f"Start {worker_index}")
    try:
        while True:
            adapter.debug(f"Starting work... {count}")
            time.sleep(1)
            count += 1
    except KeyboardInterrupt:
        print("Uset interrupt. Stop")

my_logger.py

Utilize LoggerAdapter to prepend some extra data for each log message. Each instance(worker process) could customize these extra data

#!/usr/bin/env python3

import logging
import logging.handlers
import sys

class WorkerAdapter(logging.LoggerAdapter):
    def __init__(self, logger, extra=None):
        super().__init__(logger, extra or {})

    def process(self, msg, kwargs):
        return f"[Worker {self.extra['worker_index']}] {msg}", kwargs

def logger_process(log_queue):
    queue_logger = logging.getLogger("queue-logger")
    stdout_handler = logging.StreamHandler(sys.stdout)
    stdout_handler.setFormatter(logging.Formatter("%(asctime)s | %(message)s"))
    stdout_handler.setLevel(logging.DEBUG)
    queue_logger.addHandler(stdout_handler)

#    while any(p.is_alive() for p in processes) or not log_queue.empty():
    print("Start QueueHandler")
    try:
        while True:
            record = log_queue.get()
            queue_logger.handle(record)
    except KeyboardInterrupt:
        print("Uset interrupt. Stop")

Test

❯ python3 main.py
Start 0
Start 1
Start QueueHandler
2024-02-18 21:33:02,238 | [Worker 0] Starting work... 0
2024-02-18 21:33:02,242 | [Worker 1] Starting work... 0
2024-02-18 21:33:03,239 | [Worker 0] Starting work... 1
2024-02-18 21:33:03,244 | [Worker 1] Starting work... 1
2024-02-18 21:33:04,240 | [Worker 0] Starting work... 2
2024-02-18 21:33:04,249 | [Worker 1] Starting work... 2
2024-02-18 21:33:05,241 | [Worker 0] Starting work... 3
2024-02-18 21:33:05,254 | [Worker 1] Starting work... 3
^CUset interrupt. Stop
User interrupt. Stop
User interrupt. Stop
User interrupt. Stop