본문 바로가기

(개인Project)_개발/PLC-PC 연결

[Program][보족] Ctrl+C로 서버를 껐더니 traceback이 쏟아졌다 : FastAPI CancelledError 억제하는 방법

반응형

이런 경험 있으신가요?

FastAPI 서버를 개발하다가 Ctrl+C를 눌러서 종료했을 때, 콘솔에 이런 내용이 쭉 출력됩니다.

INFO:     Shutting down
ERROR:    Exception in ASGI application
Traceback (most recent call last):
  File "...", line ..., in ...
  ...
asyncio.exceptions.CancelledError

서버가 종료되긴 했는데 마지막에 오류가 남습니다.

더 이상한 건 항상 나오는 게 아닙니다. 어떨 때는 깔끔하게 꺼지고, 어떨 때는 traceback이 쏟아져요.

재현이 잘 안 되니까 원인을 찾기도 어렵습니다.

"그냥 무시하면 되는 거 아닌가?"라는 생각도 들지만, 실제 오류 로그와 섞이면 구분이 어려워집니다.

운영 환경에서는 오류 로그가 알람으로 연결되는 경우도 있어서, 이 "가짜 오류"가 계속 울리면 진짜 오류를 놓칠 수 있어요.

PLCLink에서 정확히 같은 문제가 있었고, 원인이 두 단계에 걸쳐 있었습니다. 하나씩 풀어볼게요.


용어 먼저 짚고 넘어갈게요

asyncio CancelledError란

Python asyncio에서 실행 중인 비동기 작업이 "취소됐다"고 알리는 신호입니다.

서버가 종료될 때 진행 중인 작업들에게 "지금 하던 거 멈춰"라는 신호를 보내는데, 이 신호가 CancelledError 형태로 전달됩니다.

택배 비유로 설명하면 이렇습니다.

택배 기사가 배달하러 가는 도중에 "오늘 배달 다 취소됐어요"라는 연락을 받는 것과 같아요.

배달을 멈추는 건 당연한데, 이 연락을 받았다는 것 자체가 오류처럼 기록되는 상황입니다.

 

ASGI란

Python 웹 서버와 앱이 대화하는 방식입니다.

FastAPI가 ASGI 기반으로 만들어져 있어요.

HTTP 요청이 들어오면 ASGI 프로토콜을 통해 FastAPI 앱으로 전달됩니다.

 

미들웨어란

요청이 앱에 도달하기 전, 또는 응답이 나가기 전에 중간에서 뭔가를 처리하는 코드입니다.

보안 헤더를 붙이거나, 로그를 남기거나, 캐시를 제어하는 용도로 씁니다.

편의점 비유로 설명하면 계산대 앞에 놓인 "이달의 신상품 추천 코너" 같은 거예요.

손님이 결제하러 가기 전에 반드시 거쳐야 하는 공간입니다.

 

BaseHTTPMiddleware란

FastAPI에서 미들웨어를 만드는 편리한 방법입니다.

상속받아서 dispatch 메서드만 구현하면 됩니다.

편하긴 한데, 내부 구조가 복잡합니다. 이게 이번 버그의 첫 번째 원인이에요.


문제의 시작 : no-cache 헤더

PLCLink는 Vite로 빌드한 React 앱을 FastAPI가 서빙합니다.

빌드하고 배포했는데 브라우저가 이전 버전 HTML을 캐시해서 새 코드가 안 반영되는 문제가 있었어요.

해결책은 HTML 응답에 Cache-Control: no-cache 헤더를 붙이는 것이었습니다.

FastAPI에 미들웨어를 추가하면 됩니다.

from starlette.middleware.base import BaseHTTPMiddleware

class NoCacheHTMLMiddleware(BaseHTTPMiddleware):
    async def dispatch(self, request, call_next):
        response = await call_next(request)
        if "text/html" in response.headers.get("content-type", ""):
            response.headers["Cache-Control"] = "no-cache"
        return response

app.add_middleware(NoCacheHTMLMiddleware)

이렇게 추가하고 나서 Ctrl+C로 서버를 종료하면 traceback이 나오기 시작했습니다.


첫 번째 원인 : BaseHTTPMiddleware의 내부 구조

BaseHTTPMiddleware는 편리하지만 내부에서 anyio.create_task_group()을 사용합니다.

anyio task group은 여러 비동기 작업을 묶어서 관리하는 도구예요.

그런데 이 task group 안에서 CancelledError가 발생하면, anyio가 내부적으로 이 오류를 다시 감싸서(re-wrap) 처리합니다.

이 과정에서 traceback이 생성되고, uvicorn이 이를 ERROR 레벨로 로깅합니다.

종이컵 비유로 설명하면 이렇습니다.

종이컵 홀더(anyio task group)에 음료가 담겨 있는데, 홀더를 든 채로 "다 버려!"라는 신호가 오면 홀더가 내용물을 어떻게 처리해야 하는지 몰라서 소란이 생기는 것과 같아요.

 

해결 방법은 BaseHTTPMiddleware를 쓰지 않고, 순수 ASGI 미들웨어로 교체하는 것입니다.

# BaseHTTPMiddleware 제거, 순수 ASGI 미들웨어로 교체
class _NoCacheHTMLMiddleware:
    def __init__(self, app):
        self.app = app

    async def __call__(self, scope, receive, send):
        if scope["type"] != "http":
            await self.app(scope, receive, send)
            return

        async def send_with_nocache(message):
            if message["type"] == "http.response.start":
                headers = dict(message.get("headers", []))
                ct = headers.get(b"content-type", b"").decode()
                if "text/html" in ct:
                    # no-cache 헤더 추가
                    hdrs = list(message["headers"])
                    hdrs.append((b"cache-control", b"no-cache"))
                    message = {**message, "headers": hdrs}
            await send(message)

        await self.app(scope, receive, send_with_nocache)

이 방식은 anyio.create_task_group()을 쓰지 않습니다.

ASGI의 send callable을 직접 감싸는 방식이라, 취소 신호가 오면 그냥 위로 전파됩니다.

소란이 없어요.


그런데도 계속 나왔다 : 두 번째 원인

미들웨어를 고쳤는데 traceback이 여전히 나오는 경우가 있었습니다.

더 깊이 로그를 살펴보니 두 번째 원인이 있었어요.

asyncio.wait_for(asyncio.open_connection(host, port))
         ↑ 이 TCP 연결 시도 중에 Ctrl+C를 누르면 CancelledError 발생

PLCLink는 서버에서 PLC와 TCP로 통신합니다.

AlarmPoller나 CanvasPoller가 1초마다 PLC에 연결해서 값을 읽어요.

이때 PLC가 오프라인 상태라면 open_connection()이 타임아웃까지 기다리는 동안 Ctrl+C를 누르면 연결 시도가 취소되면서 CancelledError가 납니다.

 

이래서 "어떨 때는 나오고 어떨 때는 안 나왔던" 것이었습니다.

상황 동작
PLC 연결 완료 상태에서 Ctrl+C 취소할 TCP 연결 시도 없음 → 조용히 종료
PLC 오프라인 + 폴링 활성 상태에서 Ctrl+C 연결 시도 중 취소됨 → CancelledError
폴링이 비활성화된 상태에서 Ctrl+C 연결 시도 없음 → 조용히 종료

CancelledError를 catch해서 다른 예외로 바꾸면 안 되는가

자연스럽게 드는 생각입니다. "그냥 try-except CancelledError로 잡아서 무시하면 되지 않나?"

asyncio에서는 이렇게 하면 안 됩니다.

Python asyncio의 규약에 따라, CancelledError는 반드시 위로 전파해야 합니다.

취소 신호를 받은 작업이 그 신호를 삼켜버리면, 상위 작업은 "이 작업은 정상적으로 완료됐다"고 착각합니다.

그러면 취소 신호가 소실되고, 서버 종료가 지연되거나 리소스 누수가 생길 수 있어요.

건물 화재 대피 신호 비유로 설명하면 이렇습니다.

화재 경보(CancelledError)가 울리면 건물 밖으로 나가야(위로 전파) 합니다.

중간에 누군가가 경보를 끄고(catch해서 삼킴) "별거 아니에요"라고 하면, 건물 전체가 화재 상황인지 모르게 됩니다.

이게 더 위험해요.

CancelledError를 잡으면 전파는 해야 합니다.

try:
    await asyncio.open_connection(host, port)
except asyncio.CancelledError:
    raise  # 반드시 다시 던져야 함
except Exception as e:
    log.error(f"연결 실패: {e}")

이렇게 해도 CancelledError는 위로 전파되고 traceback은 여전히 나와요. 오류 자체를 막을 수는 없습니다.


최종 해결 : 로그 필터로 억제

CancelledError는 전파를 유지해야 합니다.

서버 종료 프로세스도 정상적으로 진행해야 해요.

그러면서 콘솔에 traceback이 출력되지 않게 하려면, 로그 자체를 필터링하는 게 올바른 방법입니다.

uvicorn의 에러 로거에 필터를 달아서, 서버 종료 시 발생하는 이 패턴의 로그만 억제합니다.

import logging

class _SuppressShutdownCancelled(logging.Filter):
    def filter(self, record):
        if record.levelno >= logging.ERROR:
            msg = record.getMessage()
            # 종료 시 발생하는 CancelledError 패턴만 억제
            if "CancelledError" in msg:
                return False
            if "Exception in ASGI application" in msg:
                return False
        return True  # 나머지 오류는 정상 출력

# uvicorn 에러 로거에 필터 적용
logging.getLogger("uvicorn.error").addFilter(
    _SuppressShutdownCancelled()
)

이 필터는 "CancelledError"나 "Exception in ASGI application" 문자열이 포함된 ERROR 레벨 로그만 억제합니다.

다른 실제 오류 로그는 영향받지 않아요.

 

결과는 이렇습니다.

# 수정 전
INFO:     Shutting down
ERROR:    Exception in ASGI application
Traceback (most recent call last):
  ...
asyncio.exceptions.CancelledError

# 수정 후
INFO:     Shutting down
INFO:     Finished server process [1234]

두 줄만 출력됩니다. 깔끔합니다.


두 수정의 역할 정리

두 가지 수정이 각각 다른 역할을 합니다.

 

첫 번째 수정 (BaseHTTPMiddleware → 순수 ASGI 미들웨어):

BaseHTTPMiddleware가 anyio task group을 쓰면서 생기는 traceback을 없애줍니다.

이건 미들웨어 구조 자체의 문제였어요.

 

두 번째 수정 (로그 필터):

PLC TCP 연결 시도 중 취소로 발생하는 traceback을 없애줍니다.

이건 PLC가 오프라인일 때만 발생하는 간헐적 문제였어요.

두 수정이 없으면 각각의 케이스에서 traceback이 나옵니다.

둘 다 적용해야 종료 로그가 완전히 깔끔해집니다.


정리

원인 증상 해결
BaseHTTPMiddleware + anyio task group 항상 발생 순수 ASGI 미들웨어로 교체
PLC TCP 연결 시도 중 서버 종료 PLC 오프라인 상태에서만 발생 uvicorn 로그 필터 적용

CancelledError는 catch해서 삼키면 안 됩니다. 전파를 유지하되, 로그만 필터링하는 것이 올바른 방법입니다.


마치며

"어떨 때는 나오고 어떨 때는 안 나온다"는 현상은 디버깅하기 가장 어려운 종류입니다.

이 경우는 PLC의 연결 상태에 따라 달라졌어요.

PLC가 응답하는 상태에서 종료하면 문제없고, 오프라인 상태에서 종료하면 traceback이 나왔습니다.

개발 환경에서는 PLC를 항상 연결해두기 때문에 눈치채기 어려웠어요.

"실제 운영 환경에서 PLC가 꺼진 상태로 서버를 종료하는 경우"라는 특수한 조건이 필요했습니다.

이런 간헐적 오류를 만나면 "언제 나오고 언제 안 나오는가"의 차이를 찾는 게 먼저입니다.

이 경우는 "PLC 연결 상태"가 그 차이였어요.

반응형