Apache 에러 로그가 0바이트인데 계속 쓰고 있었던 이유: 지워진 inode

웹사이트가 간헐적으로 이상해서 Apache 에러 로그를 열었더니 파일 크기가 0바이트였습니다. 에러가 하나도 없다는 뜻처럼 보이지만, 같은 시간대에 nginx 로그에는 문제가 잔뜩 찍혀 있었습니다. Apache만 조용할 리가 없었습니다.

Apache는 계속 로그를 쓰고 있었습니다. 다만 제가 보고 있는 파일이 아니라, 이미 지워진 파일에 쓰고 있었습니다.

지워진 파일에 계속 쓰는 이유

리눅스에서 프로세스는 파일을 이름이 아니라 열어 둔 파일 핸들(파일 디스크립터)로 씁니다. 로그 로테이션이 원래 로그 파일을 압축하고 지운 뒤 같은 이름으로 빈 파일을 새로 만들어도, Apache가 그 사실을 모르면 예전 핸들을 그대로 쥐고 계속 씁니다.

그 결과는 이렇습니다.

• 새로 생긴 로그 파일은 계속 0바이트
• Apache가 쓰는 내용은 이름 없는(지워진) 파일로 들어감
• 그 파일은 디스크 공간을 계속 차지하지만 ls에는 안 보임

보통 로테이션 도구는 파일을 바꾼 뒤 Apache에 "로그 파일 다시 열어라" 신호를 보냅니다. 이 신호가 빠지거나 실패하면 이 상태가 됩니다. 작업 기록을 보면 이 NAS에서는 7월 중순 로테이션 이후로 이 상태였습니다.

진짜 로그를 찾아 읽는 법

프로세스가 연 파일은 /proc/<pid>/fd/에 목록으로 보입니다. 지워진 파일은 링크 대상 끝에 (deleted)가 붙습니다.

# Apache 프로세스 번호 찾기
ps -eo pid,user,args | grep httpd24 | grep -v grep

# 그 프로세스가 연 파일 중 지워진 것
ls -l /proc/<pid>/fd | grep deleted
# 출력 예: ... 6 -> /var/packages/Apache2.4/var/log/apache24-error_log (deleted)

파일은 지워졌어도 핸들이 살아 있는 동안은 내용을 읽을 수 있습니다. 그 번호로 직접 읽으면 됩니다.

tail -n 100 /proc/<pid>/fd/6

제 경우는 6번이었습니다. 이 NAS에서는 Apache가 다른 사용자로 돌아서 일반 계정으로는 /proc/<pid>/fd를 열 수 없었고, root 권한으로 들어가야 했습니다. lsof가 있는 시스템이라면 lsof +L1로 "지워졌는데 열려 있는 파일"을 한 번에 볼 수도 있습니다.

같은 조사에서 한 사이트가 .htaccess의 옛 Apache 문법 때문에 500을 반복하던 것도 찾았는데, 그 배경은 해킹 흔적이었습니다.

고치는 방법

Apache가 로그 파일을 다시 열게 하면 됩니다. 시놀로지에서는 Web Station을 재시작하면 Apache가 새로 뜨면서 지금 이름의 파일을 다시 엽니다. 동시에 지워진 파일이 쥐고 있던 디스크 공간도 풀립니다.

9월 27일에 다시 확인해 보니 지금은 정상입니다. 로그 파일이 약 900KB이고, 마지막 수정 시각이 전날로 찍혀 계속 쌓이고 있습니다.

ls -la /var/packages/Apache2.4/var/log/
# apache24-error_log        907283  Sep 26 10:14
# apache24-error_log.1.xz    71148  Jun  1 22:13
# ...

로테이션 방식에 따라 생기기도, 안 생기기도 합니다

로그 로테이션에는 크게 두 가지 방식이 있습니다.

시놀로지 패키지의 로그 로테이션을 제가 직접 바꾸지는 않았습니다. 다만 이 현상을 한 번 겪고 나니, 로그가 조용할 때 파일 핸들부터 보는 습관이 생겼습니다.

로그가 조용하면 의심할 것

이 NAS는 nginx와 Apache 모두 접근 로그가 꺼져 있어서, 문제를 볼 수 있는 건 사실상 에러 로그뿐입니다. 그 에러 로그가 두 달 넘게 엉뚱한 곳에 쌓이고 있었던 겁니다. 로그가 비어 있을 때는 "문제가 없다"보다 "로그가 제대로 쓰이고 있나"를 먼저 보는 게 맞았습니다.