fail2ban 잼 세 개가 161일 동안 0건이었다, 이유는 셋 다 달랐다
서버에 fail2ban을 올려 둔 것은 2026년 4월 1일입니다. 설정 파일에는 “악성 User-Agent 봇 차단”, “취약점 스캔 차단”, “가짜 GoogleBot 차단” 같은 주석이 붙어 있었고, 저는 그동안 그 세 줄이 제 몫을 하고 있다고 믿었습니다. 오늘 상태를 처음으로 열어 봤습니다. 다섯 개 잼 가운데 웹을 지키는 세 개가 161일 동안 단 한 건도 잡지 않았습니다. 더 이상한 것은 이유가 셋 다 달랐다는 점입니다.
잼 다섯 개 중 세 개가 0건
fail2ban-client status로 각 잼의 누적 수치를 확인하고, 로테이션된 로그까지 합쳐 실제 차단 기록을 세어 봤습니다.
| 잼 | 보는 로그 | 감지 | 차단(전체 기간) |
|---|---|---|---|
| sshd | journal | 9,540 | 118 |
| apache-auth | error_log | 470 | 10 |
| apache-badbots | access_log | 0 | 0 |
| apache-botsearch | access_log | 0 | 0 |
| apache-fakegooglebot | access_log | 0 | 0 |
0이 나쁜 값이라고 단정할 수는 없습니다. 막을 것이 없어서 0일 수도 있기 때문입니다. 그래서 같은 기간 접속 로그를 먼저 읽었습니다.
그 사이 로그에는 무엇이 들어왔나
9월 6일 0시부터 9월 9일 17시까지, 3.7일치 접속 로그를 전수로 파싱했습니다. 요청 314,551건, 서로 다른 IP 18,938개였습니다. 응답 코드는 200이 215,619건, 404가 87,353건이었고, 404가 향한 주소는 21,846종이었습니다.
| 노린 대상 | 요청 수 | 비고 |
|---|---|---|
| .git 경로 | 45,136 | 저장소가 그대로 올라가 있는지 확인 |
| xmlrpc.php | 16,617 | POST 16,519건, 응답 200이 16,510건 |
| .env 계열 | 11,112 | .env.bak, .env.production 등 변형 포함 |
| wp-login.php | 7,115 | POST 4,720건 |
| phpMyAdmin 경로 | 110 | 이름 대소문자 변형 포함 |
한 IP는 3시간 동안 15,212건을 보냈고 그중 15,199건이 404였습니다. 요청한 주소가 거의 전부 서로 달랐습니다. 목록을 들고 순서대로 두드리는 도구입니다.
로그인 시도 4,720건, 성공은 0건
POST /wp-login.php 4,720건은 서로 다른 IP 776개에서 왔습니다. 리퍼러를 보면 damyo.net이 2,041건, kilho.org가 1,563건이었습니다. 응답 코드는 4,720건 전부 200이었습니다. 워드프레스는 로그인에 실패하면 200으로 로그인 화면을 다시 그리고, 성공하면 302로 관리자 화면으로 보냅니다. 302가 한 건도 없었으니 뚫린 시도는 없었다는 뜻입니다.
xmlrpc.php 쪽 응답 크기는 419바이트와 421바이트에 16,369건이 몰려 있었습니다. 인증 실패를 돌려주는 짧은 XML입니다. 이쪽도 결과는 같지만, 시도 자체가 로그인 화면보다 3.5배 많았습니다.
원인 1 — 필터가 읽는 로그가 달랐다
apache-botsearch부터 봤습니다. 이 필터의 앞부분은 이렇게 생겼습니다.
prefregex = ^%(_apache_error_client)s (?:AHd+: )?<F-CONTENT>.+</F-CONTENT>$
failregex = ^(?:File does not exist|script not found or unable to stat): <webroot><block>
webroot = /var/www/_apache_error_client은 [client 1.2.3.4] 형태를 요구합니다. 이것은 error_log에만 있는 조각입니다. 그런데 제 설정은 이 필터에 access_log를 물려 두었습니다. 형식이 아예 다르니 매칭이 될 수가 없습니다. 접속 로그 20만 줄로 fail2ban-regex를 돌려 확인했더니 0건이었습니다.
여기서 끝이 아니었습니다. webroot 기본값이 /var/www/인데 이 서버의 문서 루트는 /home/www/입니다. 로그 파일을 바로잡아도 경로가 어긋나 또 0이 됩니다. 그리고 세 번째로, error_log에는 “File does not exist” 줄이 0건이었습니다. 워드프레스의 404는 아파치가 아니라 PHP가 처리하기 때문에 아파치는 파일이 없다는 오류를 남기지 않습니다. 조건이 세 겹으로 어긋나 있었습니다.
원인 2 — 봇 사전이 2000년대 것이었다
apache-badbots는 날짜 해석까지는 정상이었습니다. 접속 로그 20만 줄에서 날짜 형식은 20만 건 전부 인식했는데, 실패 패턴만 0건이었습니다. 이 필터가 들고 있는 User-Agent 사전 90종을 꺼내 로그와 대조했습니다.
| 사전에 있는 이름 | 로그의 실제 상위 봇 | 3.7일 요청 |
|---|---|---|
| EmailSiphon | GPTBot/1.4 | 36,260 |
| Atomic_Email_Hunter/4.0 | SemrushBot/7~bl | 32,441 |
| DSurf15a 01 | Amazonbot/0.1 | 24,884 |
| Missouri College Browse | ClaudeBot/1.0 | 16,125 |
| Mac Finder 1.0.xx | MJ12bot/v1.4.8 | 7,150 |
로그에 찍힌 User-Agent는 5,262종이었는데 사전 90종과 겹치는 줄은 0이었습니다. 필터는 고장 나지 않았습니다. 사전이 지금 오는 봇을 모를 뿐입니다.
다만 이쪽은 사전을 채우는 것이 답이 아닙니다. 위 목록의 상위 넷은 검색·AI 크롤러라 막으면 색인 쪽이 손해입니다. 사전을 늘리는 일은 어느 봇을 포기할지 정한 다음에 할 일이라 오늘은 건드리지 않았습니다.
원인 3 — 날짜 형식이 필터 자신과 어긋났다
apache-fakegooglebot이 가장 뜻밖이었습니다. 배포판 필터는 이렇게 되어 있습니다.
failregex = ^s*<HOST> S+ S+(?: S+)?s+S+ "[A-Z]+ /S* [^"]*" d+ d+ ...
datepattern = ^[^[]*([{DATE}s*])fail2ban은 datepattern이 잡은 부분을 지운 다음 failregex를 적용합니다. 그런데 이 datepattern은 괄호가 대괄호 바깥까지 감싸고 있어서 시간 표기가 통째로 사라집니다. 남는 줄은 이렇게 됩니다.
원본 1.2.3.4 - - [09/Sep/2026:17:18:46 +0900] "GET / HTTP/1.1" 200 4795 ...
남은 줄 1.2.3.4 - - "GET / HTTP/1.1" 200 4795 ...failregex는 IP 뒤에 토큰이 네 개 더 있다고 보고 쓰여 있습니다. 대괄호가 지워지면 두 개뿐이라 영영 맞지 않습니다. 확인은 간단했습니다. Googlebot이라고 적힌 줄 2,601개만 뽑아 그대로 돌리면 0건인데, datepattern 한 줄만 다른 필터의 것으로 바꾸면 2,581건이 잡혔습니다. 나머지 조건은 손대지 않았습니다.
고칠 수 있는데 켜지 않은 이유
고쳐 놓고 켜지는 않았습니다. 이 잼은 “구글봇이라고 주장하는 줄”을 전부 후보로 올린 다음, 역방향 DNS 조회로 진짜만 걸러 내는 구조입니다. 즉 판정이 외부 DNS에 달려 있습니다. 조회가 잠깐 실패하면 진짜 구글봇이 방화벽에 걸립니다.
실제로 확인해 보니 Googlebot을 자칭한 IP 114개 중 97개는 검증을 통과했고 17개는 실패했습니다. 그런데 그 17개 중 11개가 클라우드플레어 대역이었습니다. 클라우드플레어를 거쳐 들어오는 방문자는 방화벽 입장에서 같은 대역으로 보입니다. 그 IP를 막으면 같은 경로로 오는 방문자까지 함께 끊깁니다. 색인이 걸린 사이트에서 감수할 위험이 아니라고 판단해 enabled = false로 두고, 이유를 설정 파일에 주석으로 적어 뒀습니다. 켜 두고 안 도는 것보다는 꺼져 있다고 적어 두는 편이 정확합니다.
무엇을 바꿨나
세 가지를 손댔습니다. botsearch는 error_log로 옮기고 webroot를 실제 경로로 맞췄습니다. fakegooglebot은 위와 같은 이유로 껐습니다. 그리고 실제로 들어오는 공격을 잡을 잼을 새로 만들었습니다.
[Definition]
failregex = ^<HOST> -.*"POST /+(?:wp-login.php|xmlrpc.php)
datepattern = ^[^[]*[({DATE})failregex를 날짜 위치에 기대지 않는 형태로 썼습니다. 원인 3에서 본 함정을 그대로 밟지 않기 위해서입니다. 잼 값은 다음과 같이 정했습니다.
| 값 | 설정 | 근거 |
|---|---|---|
| maxretry | 10 | 10분 안에 10회 이상 시도한 IP 109개가 전체 시도의 90.8%를 차지 |
| findtime | 10분 | 같은 기준을 3회로 낮춰도 94.1%, 이득이 3.3%p뿐 |
| bantime | 1시간 | 정상 사용자가 비밀번호를 헤맬 여지를 남기는 선 |
| ignoreip | 클라우드플레어 대역 | 프록시 뒤 방문자를 함께 끊지 않기 위해 |
fail2ban-client --test로 문법을 확인하고 재시작했습니다. 20초 만에 394건을 감지하고 첫 IP를 차단했습니다. 접속 로그 전체로 필터를 돌리면 31,723줄이 걸립니다. 161일 동안 0이던 자리입니다.
이틀 전 예측은 맞았나
9월 7일에 접속 로그가 두 곳에 중복 기록되던 것을 고치면서 주당 62.5MB가 줄 것이라고 적었습니다. 같은 파일 안에 고치기 전 하루와 고친 뒤 하루가 다 들어 있어 검산이 됩니다. 그때 계산과 맞춰 봤습니다.
| 구분 | 9월 6일(고치기 전) | 9월 8일(고친 뒤) |
|---|---|---|
| 요청 수 | 77,757 | 109,419 |
| 로그 크기 | 24,907,781B | 24,781,335B |
| 요청당 로그 | 320.3B | 226.5B |
9월 8일 요청량에 고치기 전 단가를 곱하면 33.43MB가 나옵니다. 실제로는 23.63MB였으니 하루 9.79MB, 주로 환산하면 68.6MB입니다. 예측 62.5MB보다 큰데, 절감률이 좋아진 것이 아니라 요청이 늘어서 그렇습니다. 단가는 예측과 같은 자리에 있었습니다.
같은 것을 확인하는 순서
이번에 밟은 순서를 그대로 적어 둡니다. 어느 서버든 fail2ban을 켜 두었다면 15분이면 끝나는 점검입니다.
fail2ban-client status로 잼 목록을 뽑고, 각 잼마다status <잼이름>을 돌려 감지·차단 수를 봅니다.- 0인 잼이 있으면 먼저 로그 쪽을 봅니다. 정말 들어온 것이 없어서 0인지, 들어왔는데 못 잡아서 0인지가 갈리는 지점입니다.
- 못 잡은 쪽이면
fail2ban-regex <로그파일> <필터파일>로 필터를 직접 돌려 봅니다. 날짜 형식이 몇 건 인식됐는지도 같이 나옵니다. - 날짜는 인식되는데 실패 패턴만 0이면 필터 내용이 로그와 안 맞는 것이고, 날짜부터 0이면 로그 형식 자체가 다른 것입니다.
- 필터를 고쳤으면 켜기 전에
fail2ban-client --test로 문법을 보고, 재시작한 뒤 몇 분 있다가 감지 수가 실제로 오르는지 확인합니다.
세 번째 단계가 핵심입니다. 필터를 로그에 직접 대 보기 전까지는, 설정이 맞다는 근거가 “그렇게 적혀 있다”밖에 없습니다. 저도 이번에 fakegooglebot의 원인을 짐작으로는 다르게 짚었다가 이 명령으로 뒤집었습니다. 처음에는 응답 바이트가 -로 찍히는 줄 때문이라고 생각했는데, 실제로 돌려 보니 원인은 날짜 쪽이었습니다.
정리
세 잼의 0은 전부 다른 이유였습니다. 하나는 읽는 파일이 달랐고, 하나는 사전이 낡았고, 하나는 필터 안에서 두 줄이 서로 어긋나 있었습니다. 공통점은 어느 것도 오류를 내지 않았다는 것입니다. 설정은 유효했고 서비스는 정상이었고 상태 출력에도 시작되었다고 찍혀 있었습니다. 숫자를 열어 보기 전까지는 문제가 있다는 신호가 어디에도 없었습니다.
봇 차단 설정처럼 켜 두면 알아서 돈다고 여기는 종류의 설정은 특히 그렇습니다. 넣고 나서 잡은 건수를 한 번도 확인하지 않으면, 있는 것과 없는 것의 차이를 알 방법이 없습니다. 저는 161일 동안 확인하지 않았습니다. 앞으로는 이런 설정을 넣을 때 무엇이 몇 건 잡히면 정상인지를 같이 적어 두려고 합니다. 그 숫자가 있어야 0이 좋은 신호인지 나쁜 신호인지 구분됩니다.
