로그 파일이 한 번 갈리자 실시간 탐지가 거기서 멈췄다

배치에서 되던 탐지를 실시간으로 옮기면 무엇이 달라지나

파일 하나를 통째로 읽어 탐지하는 것과, 지금 쌓이는 줄을 따라가며 탐지하는 것은 코드로 보면 차이가 크지 않다. 파일을 끝으로 옮겨 놓고 새 줄을 기다리는 반복문 하나면 된다.

규칙은 그대로 쓰면 되니까 금방 끝날 작업이라고 봤다.

하지만 본문에 남은 구성을 앞선 글들과 대조하면, 반복문뿐 아니라 빈도 집계와 세션 판정 방식도 달라져 있다. 이 글은 그 실시간 구성에서 탐지 지연·반복 경보·로그 회전 유실을 관찰한 기록이다. 느린 열거의 첫 경보는 8분 뒤에 나왔고, 전체 경보는 623건이었고, 로그 파일을 자르는 실행에서는 절반 가까운 줄을 잃었다. 이 결과를 모두 루프 하나의 효과로 해석할 수는 없다.

tail 루프가 하는 일

전체 흐름은 다섯 줄이다.

Python

with open(path, encoding="utf-8", errors="ignore") as log_file:
    log_file.seek(0, 2)          # 지금까지 쌓인 것은 건너뛴다
    while True:
        line = log_file.readline()
        if not line:
            time.sleep(0.5)      # 새 줄이 없으면 잠깐 쉰다
            continue
        ...                      # 파싱 → 규칙 → 경보

seek(0, 2)가 파일 끝으로 이동해 시작 시점 이전의 로그를 건너뛴다. 파일은 반복문 밖에서 한 번만 열어야 읽기 위치가 유지된다. 새 줄이 없을 때 쉬지 않으면 CPU를 계속 태운다.

배치와 다른 점이 여기 이미 들어 있다. 배치는 파일이 다 있는 상태에서 시작하지만 이 루프는 아직 안 온 줄을 기다린다. 그래서 ’지금까지 본 것’만으로 판단해야 하고, 뒤를 돌아볼 수 없다.

로그를 실시간처럼 흘려보내는 장치

측정에는 앞선 글에서 쓴 로그(19155줄, 공격 600건)를 그대로 썼다. 실시간을 흉내 내려고 스레드 두 개를 뒀다.

쓰는 쪽 — 원본 로그를 시각 순서대로 live.log에 한 줄씩 덧붙인다. 줄 사이의 로그 시각 간격을 2000배로 압축해 한 시간을 몇 초에 흘려보낸다.
읽는 쪽 — 위의 tail 루프. live.log를 따라가며 파싱하고 규칙을 적용한다.

배속과 sleep 하한 때문에 재생이 원본 간격과 정확히 같지는 않다. 그래서 탐지 지연은 실제 경과 시간이 아니라 로그에 적힌 시각으로 쟀다. 공격자의 첫 요청 시각과 그 IP에 대한 첫 경보 시각의 차이다.

얹은 규칙은 셋이다. 시그니처는 요청 경로를 두 번 디코딩해 검사하고, 빈도는 60초 슬라이딩 창에서 5건을 넘으면 잡고, 세션은 5분마다 그때까지 쌓인 IP별 기록으로 경로 중복 없이 일정한 간격으로 도는 주체를 찾는다.

앞선 빈도 탐지 실습은 resample("1min")으로 고정된 1분 구간을 집계했다. 이번에는 최근 60초를 따라 움직이는 창을 썼다. 세션 이상 탐지 실습의 순위는 Isolation Forest가 계산했지만, 여기서는 요청 수·경로 중복·간격 조건으로 열거를 판정한다. 따라서 배치와 실시간의 결과를 비교할 때는 입력이 쌓이는 방식과 탐지 방식이 함께 바뀌었다는 점을 전제로 해야 한다.

1. 탐지가 언제 나오는가

앞선 배치 실습에서는 전체 파일을 읽은 뒤의 집계와 이상 점수 순위를 봤다. 이번에는 공격자의 첫 요청부터 첫 경보까지 얼마나 걸렸는지도 기록했다.

흘려보낸 줄 19155 / 읽은 줄 19155 / 파싱 19134 / 경보 623건

공격자              정체               첫 요청     첫 경보       지연  규칙
203.0.113.10     sqli         09:12:00 09:12:00       0초  시그니처/SQLi
203.0.113.20     xss          09:25:00 09:25:00       0초  시그니처/XSS
203.0.113.30     traversal    09:33:00 09:33:00       0초  시그니처/Traversal
203.0.113.40     scan         09:41:00 09:41:00       0초  빈도
203.0.113.50     sqli_double  09:48:00 09:48:00       0초  시그니처/SQLi
203.0.113.80     enum         09:02:00 09:10:00     480초  세션/규칙적 열거

여섯 중 다섯이 첫 요청과 동시에 잡혔다. 넷은 시그니처가 잡았는데, 그 줄 하나만 보면 판단이 끝나기 때문이다. 스캐너는 이유가 다르다 — 빈도 탐지는 창이 차야 하지만 1분에 300건을 던지므로 그 창이 첫 몇 초 만에 찬다. 결과는 같아 보여도 앞의 넷은 ‘한 줄로 판단이 끝나서’ 즉시고, 스캐너는 ‘너무 빨라서’ 즉시다.

느린 열거 공격만 8분 걸렸다. 이 공격은 요청 하나로는 판단할 수 없고 「20건 이상 쌓였고 경로가 겹치지 않고 간격이 일정하다」가 성립해야 잡힌다. 약 17초 간격의 요청이 여러 분 동안 쌓여야 하고 판정도 5분마다 이루어진다. 이 실행에서 첫 경보가 기록된 시각은 첫 요청으로부터 480초 뒤였다.

앞선 배치 실습에서 열거 공격자는 Isolation Forest의 이상 점수 순위로 ’2등’이었다. 여기서 나온 480초는 별도의 규칙 기반 탐지에서 측정한 첫 경보 지연이다. 같은 모델을 실시간으로 옮겼더니 8분 늦어졌다는 뜻은 아니다. 이번 구성에서는 그 시간 동안 열거가 28건쯤 진행된 뒤 첫 경보가 나왔다.

지연을 줄이는 방향은 두 갈래인데 둘 다 대가가 있다. 판정 주기를 짧게 하면 계산이 자주 돌고, 최소 요청 수를 낮추면 표본이 부족한 세션이 올라온다. 요청 3건짜리 세션의 간격 통계가 통계가 아니라는 것은 앞선 글에서 확인한 그대로다.

2. 경보가 몇 건 나오는가

같은 실행에서 경보가 623건 나왔다. 한 시간짜리 로그에서다.

억제 없음: 경보 623건
    빈도                         330
    시그니처/SQLi                  146
    시그니처/XSS                    68
    시그니처/Traversal              61
    세션/규칙적 열거                   12
    시그니처/CmdInjection            6

절반이 빈도 경보고, 그 대부분이 스캐너 하나다. 1분에 300건을 던지는 IP는 창이 찬 뒤 모든 요청마다 임계값을 넘으므로 요청 수만큼 경보가 나온다. 규칙은 정확하게 동작했다. 다만 ’이 IP가 스캔 중’이라는 사실 하나를 300번 말한다.

같은 IP·같은 규칙 조합에 5분 쿨다운을 뒀다.

같은 IP·같은 규칙 5분 쿨다운: 경보 157건 (억제 466건)
    시그니처/SQLi                   65
    시그니처/Traversal              38
    시그니처/XSS                    36
    세션/규칙적 열거                   12
    빈도                           5
    시그니처/CmdInjection            1
억제 때문에 놓친 IP: 0개

623건이 157건이 되고 빈도 경보는 330건에서 5건으로 줄었다. 확인해야 할 것은 마지막 줄이다 — 억제 때문에 아예 안 보이게 된 IP는 0개다. 줄어든 466건은 전부 이미 경보를 낸 IP의 반복이었다.

억제는 탐지를 끄는 것이 아니라 같은 사실의 반복을 접는 것이다. 다만 접는 순간 횟수 정보가 경보에서 사라지므로 억제한 건수를 함께 세어 두지 않으면 「한 번 찔러 본 IP」와 「300번 던진 IP」가 같은 경보 한 줄로 보인다.

3. 로그 파일이 갈리면

운영 중인 로그는 계속 커지므로 주기적으로 갈린다. 여기서는 Windows에서 쓰는 방식을 흉내 냈다 — 파일을 복사해 두고 원본을 0바이트로 자르는 것이다.

10000번째 줄에서 한 번 자르고, 위의 루프를 그대로 돌렸다.

위치만 따라감      흘려보낸 19155 / 읽은 10000 / 유실 9155 (47.8%) / 경보 214건
                 탐지한 공격자 4/6개 — 놓친 것: 203.0.113.40(scan), 203.0.113.50(sqli_double)

절반을 잃었다. 정확히는 자른 시점 이후로 한 줄도 못 읽었다.

이유는 readline()이 파일 이름이 아니라 읽기 위치를 따라가기 때문이다. 자르기 직전 위치는 10000줄째 끝이었는데 파일은 0바이트가 됐다. 새 줄이 그 뒤로 다시 쌓이지만, 읽기 위치는 여전히 한참 앞에 있으므로 파일이 예전 크기를 다시 넘을 때까지 readline()은 계속 빈 문자열을 돌려준다. 이 로그에서는 그 지점에 영영 도달하지 못했다.

문제는 비율이 아니라 루프가 정상으로 보인다는 점이다. 예외도 없고 오류 로그도 없다. 반복문은 계속 돌고 sleep하고 있으며 프로세스는 살아 있다. 경보가 214건에서 멈춘 것을 누가 세어 보지 않으면 ’오늘은 조용하네’로 읽힌다. 실제로 그 조용한 구간에 스캐너 300건과 이중 인코딩 공격이 들어 있었다.

읽기 위치가 파일 크기보다 뒤에 있으면 잘렸다고 보고 처음부터 다시 읽게 했다.

Python

if not line:
    if os.path.getsize(path) < pos:   # 파일이 나보다 작아졌다
        f.close()
        f = open(path, encoding="utf-8", errors="ignore")
        f.seek(0)                     # 새로 쌓인 것을 처음부터
        pos = 0
        continue
    time.sleep(0.005)
    continue

잘림 감지 후 되감기   흘려보낸 19155 / 읽은 19155 / 유실 0 (0.0%) / 경보 623건
                 탐지한 공격자 6/6개

유실 0건, 공격자 6개 전부. 회전이 없을 때와 완전히 같은 결과가 됐다.

루프에 붙여야 하는 것

앞선 배치 실습과 이번 실시간 구성에서 관찰한 차이를 나란히 놓으면 다음과 같다. 빈도 집계와 세션 판정 방식이 다르므로 동일 탐지기의 전후 성능 비교로 읽으면 안 된다.

무엇이 달라졌나	앞선 배치 실습	이번 실시간 구성
느린 공격 탐지	Isolation Forest 이상 점수 순위 2위	규칙 기반 판정의 첫 경보까지 480초
빈도 집계와 경보	고정 1분 구간, IP별 집계 결과	60초 슬라이딩 창, 억제 전 빈도 경보 330건
로그 회전	전체 파일을 읽음	파일을 자르는 실행에서 47.8% 유실, 공격자 2개 미탐

이 실시간 구성에서는 탐지 조건과 함께 다음 세 가지를 확인해야 했다.

읽기 위치가 깨지는 경우를 처리한다. 파일 크기가 읽기 위치보다 작아지면 잘린 것이다. 이 하나를 넣고 안 넣고가 47.8% 대 0%였다.
같은 사실의 반복을 접는다. 접되 접은 횟수를 세어 경보에 함께 싣는다.
여러 줄이 쌓여야 성립하는 탐지는 지연을 명시한다. 「잡힌다」와 「8분 뒤에 잡힌다」는 대응 계획이 다른 이야기다.

탐지 여부만으로는 경보가 언제 나왔고 얼마나 반복됐는지 알 수 없다. 로그 회전에서는 읽어야 할 줄을 다 읽었는가도 따로 확인해야 한다. 흘려보낸 줄 수와 읽은 줄 수를 나란히 세면 입력 유실을 볼 수 있다. 위 출력의 맨 앞 두 숫자가 그것이다.

재확인 방법

아래는 당시 실습에 사용한 명령이다. 현재 저장소에는 gen_log.py와 realtime.py가 포함돼 있지 않아, 다시 실행하려면 로그 생성기와 실시간 처리 코드를 복원해야 한다.

bash

python gen_log.py --users 800 --enum   # 로그 준비 (19155줄)
python realtime.py                     # 세 시나리오를 차례로 실행

당시 realtime.py는 스레드 두 개로 쓰는 쪽과 읽는 쪽을 동시에 돌렸다. SPEED(기본 2000)로 재생 속도를, rotate_at으로 파일을 자르는 시점을 조절했다.

측정 환경은 Python 3.14.6 / pandas 3.0.3이다. 경보는 화면 출력이고 외부로 나가는 전송은 없다.

이 글에서 확인하지 못한 것은 세 가지다. 첫째, 로그 회전을 ‘잘라내기’ 한 방식으로만 시험했다. 유닉스에서 기본인 ‘이름을 바꾸고 새 파일을 만드는’ 방식은 열린 파일의 이름을 바꾸는 것이 이 환경에서 막혀 재현하지 못했고, 그쪽은 읽기 위치가 아니라 파일 식별자를 봐야 하므로 대응 코드도 다르다. 둘째, 재시작 후 이어 읽는 체크포인트는 넣지 않았다 — 프로세스가 죽는 동안 쌓인 줄은 여전히 통째로 사라진다. 셋째, 경보 전송을 화면 출력으로 대신했으므로 전송 실패나 재시도가 루프를 멈추는지는 확인하지 못했다.

2026-09-25 정정: 당시 실행 파일이 현재 저장소에 없어 제시한 명령만으로 재현할 수 없음을 반영했다.

2026-09-26 정정: 앞선 배치 실습과 빈도 집계·세션 판정 방식이 달라진 점을 반영했다. 같은 탐지 규칙에서 루프만 바꾼 비교라는 설명을 고쳤으며, 수치를 새로 실행해 측정한 것은 아니다.