RotatingFileHandler 실측 — 두 프로세스면 로그가 샌다

1. 봇 로그는 하루에 얼마나 쌓이나 — 줄당 101바이트

자동매매 봇을 맡기신 분들이 납품 몇 달 뒤 가장 자주 보내는 문의 중 하나가 "멀쩡하던 봇이 갑자기 멈췄다"입니다. 원인을 따라가 보면 메모리 누수, 윈도우 업데이트 재부팅과 함께 로그 파일이 디스크를 채운 경우가 꾸준히 나옵니다. 처음 만들 때는 logging.FileHandler("bot.log") 한 줄이면 충분해 보이기 때문입니다.

시세 한 줄을 시각·레벨과 함께 남기는 흔한 형식으로 1만 줄을 써서 재 보니 줄당 100.9바이트였습니다.

2026-10-28 10:15:03,412 INFO tick 005930 cur_prc=-71400 trde_qty=+1203 bid=71300 ask=71400 seq=812

정규장 09:00~15:30(23,400초) 기준 계산입니다. 여기에 키움 ka10081 일봉이나 KIS FHKST03010100 같은 차트 응답을 JSON 전문 그대로 logger.debug(resp.text)로 남기면 한 번에 수십 KB씩 붙습니다. 저가형 VPS의 시스템 디스크가 수십 GB인 경우가 흔하니, 1초 단위 로그를 아무 제한 없이 두면 1~2년 안에 디스크 문제가 실제로 생깁니다. 어떤 내용을 남겨야 하는지는 매매일지·로그 기록 가이드에서 다뤘고, 이 글은 크기를 묶는 방법만 봅니다.

2. 기본 설정과 실측 결과

표준 라이브러리 logging.handlers에 크기 기준 RotatingFileHandler와 시각 기준 TimedRotatingFileHandler가 있습니다. 크기 기준의 기본형은 이렇습니다.

import logging
from logging.handlers import RotatingFileHandler

handler = RotatingFileHandler(
    "bot.log",
    maxBytes=1_000_000,   # 1MB 넘으면 회전
    backupCount=3,        # bot.log.1 ~ bot.log.3 까지만 보관
    encoding="utf-8",
)
handler.setFormatter(logging.Formatter("%(asctime)s %(levelname)s %(message)s"))
log = logging.getLogger("bot")
log.setLevel(logging.INFO)
log.addHandler(handler)

이 설정으로 위 형식의 줄을 10만 개(약 10MB) 쓴 뒤 폴더를 본 결과입니다.

bot.log      189,822
bot.log.1    999,906
bot.log.2    999,906
bot.log.3    999,906
합계       3,189,540 바이트   (10만 줄 중 최근 약 3만 줄만 남음)

회전은 "bot.log.2→bot.log.3, bot.log.1→bot.log.2, bot.log→bot.log.1로 이름을 밀고 새 bot.log를 여는" 방식입니다. 가장 오래된 bot.log.3은 지워지므로 디스크 사용량은 maxBytes × (backupCount + 1), 여기서는 4MB를 넘지 않습니다. 대신 오래된 기록은 사라진다는 뜻이라, 체결·주문 기록처럼 오래 남겨야 하는 것은 회전 로그가 아니라 CSV나 SQLite에 따로 남겨야 합니다.

3. 함정 4가지 (실측)

① backupCount=0이면 회전하지 않는다 — 10MB까지 그대로

maxBytes만 주고 backupCount를 빠뜨리면 기본값이 0입니다. 파이썬 공식 문서는 두 값 중 하나라도 0이면 회전이 일어나지 않는다고 적고 있고, 실제로 같은 10만 줄을 쓰자 이렇게 됐습니다.

RotatingFileHandler("bot.log", maxBytes=1_000_000, backupCount=0)
→ bot.log  10,188,890 바이트   (1MB 제한이 전혀 안 걸림)

에러도 경고도 없습니다. 설정 파일에 maxBytes가 보이니 "용량 제한은 걸려 있다"고 믿게 되는 게 가장 위험한 점입니다.

② 두 프로세스가 같은 파일을 쓰면 — WinError 32와 로그 소실

봇이 커지면 전략 계산과 주문 처리를 multiprocessing으로 나누거나, 감시 스크립트를 따로 띄우는 일이 생깁니다. 각 프로세스가 같은 bot.log에 각자 RotatingFileHandler를 걸면 회전 순간 윈도우가 이름 변경을 막습니다. strategy·order 두 프로세스가 각 3만 줄을 쓰고 마지막에 DONE 한 줄을 남기게 해서 세 번 돌렸습니다(maxBytes=200_000, backupCount=3).

--- Logging error ---
PermissionError: [WinError 32] 다른 프로세스가 파일을 사용 중이기 때문에 프로세스가 액세스 할 수 없습니다: '...\bot.log' -> '...\bot.log.1'

(다른 실행에서는)
PermissionError: [WinError 5] 액세스가 거부되었습니다
FileNotFoundError: [WinError 2] 지정된 파일을 찾을 수 없습니다

세 번째 실행에서 strategy는 order보다 5.6초 먼저 끝났는데, 남은 4개 파일 6,856줄은 전부 order 것이었고 strategy가 마지막에 쓴 strategy DONE은 어디에도 없었습니다. 회전에 실패한 쪽이 이미 이름이 바뀐 옛 파일에 계속 쓰다가, 그 파일이 다음 회전에서 밀려 지워진 것으로 보입니다. 에러는 --- Logging error ---로 콘솔(stderr)에 한 번 찍히고 봇은 아무 일 없다는 듯 계속 돕니다 — logging.raiseExceptions 기본값이 True여도 handleError는 출력만 하고 예외를 올리지 않기 때문입니다. 파이썬 Logging Cookbook도 "여러 프로세스에서 한 파일로 로깅하는 것은 지원하지 않는다"고 명시합니다.

③ RotatingFileHandler는 6배 느렸다

같은 10만 줄을 FileHandler로 쓰면 5.07초, RotatingFileHandler(maxBytes=50_000_000, 회전 없음)로 쓰면 31.7초였습니다. 파이썬 3.10의 shouldRollover() 소스를 보면 이유가 보입니다.

def shouldRollover(self, record):
    if os.path.exists(self.baseFilename) and not os.path.isfile(self.baseFilename):
        return False
    ...
    if self.maxBytes > 0:
        msg = "%s\n" % self.format(record)      # 같은 레코드를 한 번 더 포맷
        self.stream.seek(0, 2)                  # 매 줄 파일 끝으로 이동
        if self.stream.tell() + len(msg) >= self.maxBytes:
            return True

매 줄마다 os.path.exists·isfile 파일 조회 2번, 포맷 2번, seek가 붙습니다. 줄당 0.32ms라 초당 수십 줄 수준의 봇에서는 문제가 아니지만, 웹소켓 체결 틱(키움 0B·KIS H0STCNT0)을 받는 콜백 안에서 틱마다 log.info()를 부르면 그 시간만큼 수신 처리가 밀립니다. 4장의 큐 방식은 이 비용도 별도 스레드로 빼 줍니다. 덤으로, 크기 비교는 바이트(tell())에 글자 수(len(msg))를 더하는 방식이라 한글 로그에서는 1MB 제한 파일이 1,000,032바이트로 끝났습니다 — 이 정도는 무시해도 됩니다.

④ TimedRotatingFileHandler는 "자정 이후 첫 줄"에 회전한다

날짜별 파일이 보기 편해서 TimedRotatingFileHandler("bot.log", when="midnight", backupCount=7)를 많이 씁니다. 실측한 내부 값은 접미사 suffix = "%Y-%m-%d", 다음 회전 시각 rolloverAt = 2026-10-29 00:00:00였습니다. 회전은 자정에 타이머로 일어나는 게 아니라 자정 이후 처음 로그가 찍힐 때 일어나므로, 밤새 조용한 국내주식 봇은 다음 날 08:50 첫 로그 때 bot.log.2026-10-28이 생깁니다. 또 시간 기준은 하루 용량에 상한이 없습니다. 장중 이상으로 로그가 폭주한 날 하루 파일이 수 GB가 될 수 있으니, 크기 상한이 꼭 필요하면 크기 기준을 쓰거나 둘을 섞는 편이 낫습니다.

4. 해결 코드 — QueueHandler로 파일 여는 쪽을 하나로

표준 라이브러리만으로 됩니다. 각 프로세스는 QueueHandler로 큐에 레코드를 넣기만 하고, 메인 프로세스의 QueueListener 하나가 RotatingFileHandler로 씁니다.

import logging, logging.handlers, multiprocessing as mp

def worker(q, name):
    log = logging.getLogger(name)
    log.setLevel(logging.INFO)
    log.addHandler(logging.handlers.QueueHandler(q))   # 파일을 직접 열지 않는다
    ...                                                # 전략·주문 로직
    log.info("%s DONE", name)

if __name__ == "__main__":
    q = mp.Queue(-1)
    fh = logging.handlers.RotatingFileHandler(
        "bot.log", maxBytes=5_000_000, backupCount=10, encoding="utf-8")
    fh.setFormatter(logging.Formatter("%(asctime)s %(processName)s %(levelname)s %(message)s"))
    listener = logging.handlers.QueueListener(q, fh)   # 파일을 여는 건 이 하나뿐
    listener.start()

    ps = [mp.Process(target=worker, args=(q, n), name=n) for n in ("strategy", "order")]
    for p in ps: p.start()
    for p in ps: p.join()
    listener.stop()                                    # 남은 레코드를 다 쓰고 닫는다

2장과 같은 조건(각 3만 줄, maxBytes=200_000)으로 돌린 결과입니다.

logging errors: 0
bot.log    99,916  ['strategy DONE', 'order DONE']
bot.log.1 199,913
bot.log.2 199,919
bot.log.3 199,913

프로세스를 나누지 않는 단일 프로세스 봇이라도 QueueHandler는 쓸모가 있습니다. 웹소켓 콜백 스레드에서는 큐에 넣기만 하고 파일 쓰기와 회전 판정은 리스너 스레드가 맡아서, 3장 ③의 비용이 수신 경로에서 빠집니다. 더 단순한 대안은 프로세스마다 파일을 나누는 것(bot-strategy.log, bot-order.log)입니다. 외부 패키지 concurrent-log-handler도 있지만 윈도우에서는 pywin32가 필요해 의존성이 늘어납니다.

• 설정은 한 곳에서 — 모듈마다 logging.basicConfig()를 부르면 핸들러가 중복으로 붙어 같은 줄이 두 번 찍힙니다. 진입점(main.py)에서 한 번만 설정합니다.
• 레벨을 나눈다 — 틱·호가는 DEBUG, 주문·체결은 INFO, 예외는 ERROR. 평소엔 INFO로 돌리면 1장 표의 맨 아래 줄이 맨 위 줄 수준으로 줄어듭니다.
• 민감정보 금지 — 토큰 발급 응답이나 요청 헤더를 통째로 남기면 appkey·secretkey·Bearer 토큰이 로그 파일에 남습니다.

5. 디스크 여유 감시까지

로그를 묶어도 디스크를 채우는 것은 로그만이 아닙니다(분봉 CSV, SQLite, 윈도우 업데이트 캐시). 장 시작 전 한 번 shutil.disk_usage()로 여유 공간을 보고, 기준 아래면 텔레그램으로 알리게 해 두면 "어느 날 갑자기 멈춤"을 미리 막을 수 있습니다.

import shutil

def check_disk(path="C:\\", min_free_gb=5):
    u = shutil.disk_usage(path)
    free_gb = u.free / 2**30
    if free_gb < min_free_gb:
        notify(f"[경고] 디스크 여유 {free_gb:.1f}GB — 로그·데이터 폴더 점검 필요")   # 텔레그램 등
    return free_gb

알림 연결은 텔레그램 봇 모니터링 글, 멈춘 뒤 어떻게 복구하는지는 봇 장애 복구 플레이북, VPS 운영 전반은 VPS 24시간 운영 가이드에 정리했습니다. 작업 스케줄러로 봇을 띄운다면 그때 bot.log 경로가 상대 경로라 엉뚱한 폴더(C:\Windows\System32)에 쌓이는 경우도 있으니 작업 스케줄러 0x1 글의 "시작 위치" 설정도 같이 확인하세요.

6. 자주 묻는 질문

실측 환경: Python 3.10.4 · Windows 11(10.0.26200) · 로컬 디스크. 처리 시간과 에러 종류는 파이썬 버전·디스크·백신 설정에 따라 달라질 수 있습니다. 공식 근거: Python 문서 logging.handlers(RotatingFileHandler·TimedRotatingFileHandler·QueueHandler·QueueListener)와 Logging Cookbook.