서버 로그로 상태를 판정하다 틀리는 세 가지 실수

로그는 사실을 담고 있지만, 읽는 방법이 틀리면 정반대 결론이 나옵니다. 운영 중인 서버에서 로그만 보고 판정했다가 틀린 세 가지를 적습니다. 셋 다 명령 습관 하나로 막을 수 있었습니다.

로그를 보고 실제로 틀렸던 판정들

실수	내린 판정	실제
앞부분만 읽음	요즘 처리할 대상이 없나 보다	이틀 동안 처리 0건, 맨 끝에 크래시
파일 시각을 믿음	지금 이 설정으로 돌고 있다	그 줄은 7월 22일 것, 판정한 날은 9월 9일
head 로 자름	설정 파일이 없다	.bak 사본에 밀려 진짜 파일이 잘림

1. 크래시는 로그 맨 끝 한 덩어리에 있었다

자료 수집 작업이 이틀 동안 0건이었습니다. 로그를 열면 "쓸 대상 없음" 같은 정상 문구가 가득해서 입력이 없는 줄 알았습니다. 그 무렵 장비 하나가 꺼져 있었고 외부 서비스 잔액도 떨어져 있어서 그쪽이 원인처럼 보였지만, 둘 다 진짜 원인이 아니었습니다.

진짜 원인은 맨 끝의 트레이스백이었습니다. 결과에 새 필드를 하나 실으면서, 다른 함수 안의 지역변수 이름을 그대로 참조했습니다. 처리할 대상을 찾은 순간마다 그 줄에서 NameError 로 죽었습니다. 문법 검사는 이름이 있는 것처럼 보여 이것을 잡지 못합니다.

def search_and_pick(item):
    first = pick(item)
    return first

def main():
    for item in items:
        if search_and_pick(item):
            queue.append({"person": first})   # NameError: name 'first' is not defined

2. 파일 수정 시각은 줄의 시각이 아니다

지금 어떤 설정으로 돌고 있는지를 로그 한 줄로 판정했습니다. 로그 파일은 계속 쓰이고 있어 수정 시각은 늘 오늘이었습니다. 그래서 그 줄도 최근 것이라 읽었는데, 실제로는 7주 전 줄이었습니다.

3. head 가 진짜 파일을 잘랐다

두 번째와 세 번째 실수는 같은 날 한꺼번에 일어났습니다. 오래된 로그 줄을 근거로 "이 설정으로 돈다"고 판단했고, 그 판단을 확인하려고 설정 파일을 찾다가 head 때문에 못 찾았습니다. 틀린 근거 둘이 서로를 받쳐 주어 더 확신하게 된 것입니다.

설정값이 어디 있는지 grep 으로 찾고 결과를 head 로 잘랐습니다. 이름순으로 앞에 오는 .bak 사본들이 자리를 다 차지해, 실제로 쓰이는 설정 파일이 잘려 나갔습니다. 그걸 "설정된 곳이 없다"로 읽었습니다.

로그를 읽는 습관

로그는 끝부분부터 봅니다. 앞에 정상 문구가 많을수록 더 그렇습니다.

tail -n 80 /opt/app/logs/collect.log
grep -n -A 20 Traceback /opt/app/logs/collect.log | tail -n 40

현재 상태를 말할 때는 줄 번호와 줄 앞의 시각을 함께 찍어 봅니다. 파일의 수정 시각은 근거로 쓰지 않습니다. 줄 앞에 시각이 없는 로그라면, 로그에 시각을 남기도록 고치는 것이 먼저입니다.

grep -n "engine=" /opt/app/logs/run.log | tail -n 5

"없다"고 말하려면 사본을 먼저 빼고, 자르지 않고 셉니다. 개수부터 세어 보고 나서 내용을 보면, 잘린 결과를 전부로 착각하는 일을 막을 수 있습니다.

grep -rl "VISION_ENGINE" /opt/app --exclude='*.bak*' | wc -l
grep -rn "VISION_ENGINE" /opt/app --exclude='*.bak*'

환경변수 값은 코드의 기본값이 아니라 실제 실행에 쓰이는 env 파일에서 확인합니다. 코드의 os.environ.get(..., "기본값") 을 현재값으로 읽으면 틀립니다.

확인 방법

• 작업이 조용하면 "입력이 없어서"로 결론 내기 전에, 입력을 공급하는 쪽이 살아 있는지 봅니다.
• 눈에 보이는 원인(장비 꺼짐, 잔액 소진)이 있어도 그것으로 설명이 끝났다고 보지 않고 로그 끝을 확인합니다.
• 필드 하나를 새로 실을 때도 그 분기를 실제로 한 번 태워 봅니다. 배선만 하고 넘어가면 그 분기에 들어갈 때만 죽어 며칠 뒤에 드러납니다.

이번 크래시는 커밋 하나에서 생기고 다음 커밋에서 고쳤습니다. 실제로 쓰이는 설정은 장부 기록으로도 확인했는데, 하루 320에서 657건이 그 설정으로 처리되고 있었습니다.

로그 파일이 아예 없는 경우는 다른 문제입니다. 크론이 돈다고 찍히는데 안 돌 때를 보세요.

확인한 환경

항목	내용
운영체제	리눅스 서버, 크론으로 도는 파이썬 작업
확인한 날짜	2026년 9월 8일(크래시), 9월 9일(줄 시각, head)

이어지는 이야기: 파이썬 스크립트가 조용히 실패하는 경우

이 글의 내용은 2026년 10월 5일에 마지막으로 확인했습니다. 틀린 곳을 발견하시면 연락처로 알려 주세요.