사전 정의
- 물이 다른 물이나 물체에 부딪쳐서 생기는 거품.
- 노력이 헛되게 된 상태를 비유적으로 이르는 말. > 유의어 : 수포1, 포말3, 뜬구름
오늘 오후 지메일로부터 한통의 메일을 받았다. 당신의 사이트가 24시간 동안 크롤링이 되지 않는다. 즉, 서버가 죽었다는 말이다. 왜 죽었는지 이유는 모르겠다. 불연듯 떠오른 나의 생각은 다른거 다 제껴두고 매일 로그인해서 이벤트를 응모하도록 만들어놓은 cron 잡들이었다. 아니나 다를까! 멘붕! OTL,… 심열을 기울여 한달 스템프를 모두 받겠다고 야심차게 스크립트까지 만들어 돌렸는데,… 토요일 하루 도장이 없다! 망했다! 진짜 이번엔 성공할줄 알았는데… 제대로 한방 먹었다. ㅜㅜ 정녕 내년을 기약해야하는 것인가? ㅎㅎ
서버는 언제 죽은 것일까?
아까 낮에 허탈함에 어떻게 해야지? 어떻게 해야지? 발만 동동 굴렸는데,.. 역시 밤이 되니까 여러가지 생각을 되짚어보게 된다. 서버가 왜 죽었을까? AWS로 옮겨온 이후로 2번째다. 그리고 nginx로 넘어온 뒤로 역시 두번째다. 지난번에는 php모듈을 건들다가 발생한 문제라서 php-fpm이 문제겠꺼니 쉽게 유추해낼수있었는데.. 이번엔 도대체 뭐지?
언제 죽었는지도 알수없고, 얼마나 오랜동안 죽어있었는지 조차도 알수가 없었다. 그래! 결심했어! 찾아보자! 뚜두뚜~ 뚜두뚜~ 뚜두뚜~ 뚜뚜루루~ 뚜두뚜~ 뚜두뚜…
그래 일단 AWS에서 제공하는 모니터링 로그를 살펴보는거야!
지난 토요일에 스템프가 찍히지 않는걸로 봐서 최소 2일이상의 로그를 봐야한다. 그래서 3일짜리 네트워크 유입량부터 살펴봤다. 
아니나 다를까 12월 14일 오전 8시경 네트워크 유입량이 짧은 시간안에 엄청나게 몰렸다. UTC 기준이니까 실제 한국시간으로는 오후 5시쯤이 아닐까? 어라? 그러고보니 내가 서버를 확인한 시간이 오후 5시쯤인데 오후 5시에 죽었따고? 말이 안되는데? 쫌 이상하다! 이미 그전에 서버 응답이 없어야되고, 지메일은 분명히 지난 24시간동안 최소 1번 이상 응답이 없었다고 알림을 줬다. 그리고 이 메일을 받은 시각은 오전 10시경,.. 그렇다면 최소 어제 오전 10시 이전에 서버가 죽어 있거나 응답이 없었다는 얘기가 된다. 그래야 말이 된다. 왜냐면 내가 매일 오전 10시에 스템프를 찍도록 크론잡을 돌려놨었는데,.. 이 크론잡도 실행을 못했다는 얘기는 10시전에 서버에 뭔가 문제가 생겼다는 얘기가 된다. 다른 로그를 좀더 살펴봐야겠다.
음,.. 뭔가 추이가 이상하다. 네트워크 아웃을 보니 토요일 새벽 0시쯤 그러니까 우리나라 시각으로는 토요일 오전 9시경부터 네트워크 유입은 있지만 뭔가 서버가 응답을 못해주고 있다. CPU credit도 갑자기 뚝 떨어졌다. 아! 여기구나! 절묘하네. 토요일 오전 9시! 도대체 이날 무슨일이 있었던거지? 젠장 한시간만 늦게 죽지..ㅜㅜ 아니지.. 매일 한번씩이 아니라 6시간마다 한번씩 크론잡을 돌렸다면 적어도 문제는 없었는데…ㅜㅜ.. 아! 쉽! 다!…
토요일 오전 9시의 미스터리. 실마리를 찾아서
그럼 토요일 오전 9시경 문제가 될만한 로그부터 뒤져봐야겠다. 일단 syslog를 봐야된다길래 /var/log/syslog가 있는지 확인부터 해봤지만,.. 어머나! 없네? syslog를 찍는건 옵션을 따로 설정해야하는건가? 아~ 몰라,.. 패스.. 그럼 지난번 원인이었던 php-fpm 로그부터 보자.
$> cd /var/log/php-fpm
$> ls -al
-rw------- 1 root root 2054 12월 14 17:38 error.log
-rw------- 1 root root 20440 11월 22 22:24 error.log-20141123
-rw------- 1 root root 15612 11월 30 01:56 error.log-20141130
-rw------- 1 root root 2504 12월 6 02:36 error.log-20141207
-rw------- 1 root root 97429 12월 14 16:29 error.log-20141214
어랏? 로그파일의 크기가 0이 아닌걸로 봐서는 진짜 php-fpm에서 뭔가 문제가 있었네? 열어보자! 뚜둥!! 뭐지 이건?
$> cat error.log-20141214
... 중략 ... 핵심만 ...
ERROR: fork() failed: Cannot allocate memory (12)
WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 32 children, there are 0 idle, and 11 total
메모리를 할당할 수 없다고? 도대체 언제부터 이런거지? cat은 화면 출력 버퍼량 때문에 짤리니까 vi로 열어봐야겠다.
$> vi error.log-20141214
... 중략 ...
[12-Dec-2014 10:10:59] ERROR: fork() failed: Cannot allocate memory (12)
정확히 메모리 에러가 난 시간은 12일 오전 10시경, 참고로 리눅스 서버의 시간은 UTC 기준이었으나 크론탭을 설정할때 자꾸 헛갈려서 로컬 타임을 한국시간으로 바꿔놨다. 음,.. 그러니까 서버가 죽은 시간은 정확히 오전 10시 10분. 아! 10분만 일찍 죽었어도 12일부터 그놈의 스템프를 못찍었겠꾸나 ㅎㄷㄷ…
도대체 진짜 원인은 뭘까?
그래, php-fpm에서 처음 메모리 할당 오류가 뜬 시간이 지난 12일 오전 10시경이니까 처음 예상했던 시간보다 하루 일찍 문제가 찾아왔었군!… 그렇다면 실제 원인을 찾기 위해서 모니터링 로그를 좀더 넓혀서 살펴봐야겠다. 음.. 내가 뭔가 탐정된 느낌이군. ㅎㅎㅎ
아! 넓혀서 추이를 보니 이번엔 또 다른 단서가!! 네트워크 아웃을 보니 12일부터 밖으로 나가는 트래픽이 없어졌다. 덩달아 CPU 사용률이 훅~ 떨어지는걸 봐서는 확실히 12일부터 서버에 문제가 있었던것 같다. 그런데 그보다 앞서 CPU 사용률을 보니 지난 8일 오전 10시경부터 뭔가 CPU 사용률이 계단식으로 증가하고 있네!!! 뚜둥~! 마치 메모리 누수가 있을때 나타나는 현상처럼 증가하고 있다. 도대체 뭐지?
한편 이에 앞서 syslog를 대신할 만한 이벤트 메세지도 확인해봤다.
%> vi /var/log/message
... 중략 ....
Dec 12 10:11:10 ip-172-31-12-73 kernel: [604065.445632] php-fpm[9401]: segfault at 80001000321 ip 00000000005c8407 sp 00007fff305df290 error 4 in php-fpm[400000+325000]
... 중략 ....
Dec 12 18:17:24 ip-172-31-12-73 wordpress(miconblog.com)[8434]: Authentication failure for admin from 198.46.81.14
...
여기서 잠깐!
로그를 보니 재밌는 현상을 발견했다. php-fpm에서 메모리 할당 오류가 나면 segfault 메시지를 발생시킨다는 사실과 더불어 인도에서 내 워드프레스 계정을 털려고 시도한 흔적이 보인다는 사실이다! 아~ 인도!! IT 강자로 급부상 중이라고 하더니… 흠..좀..무.. 다시 워드프레스 계정 보안 플러그인을 설치해야겠다는 생각이든다. php-fpm 문제 해결을 위해 검색을 좀 해봤더니 설정값을 좀 늘려보라는데,.. 그게 문제겠냐? 저렇게 무차별 DDos 공격에 당하면 서버가 죽어버리는데..ㅜㅜ..
여전히 알수없는 미스터리..
다시 돌아와서 지난 8일에 내가 도대체 무슨일을 했는지.. 기억을 더듬어봤다. 일단 캘린더에 등록된 저녁 일정엔 와인동호회 모임이 있었음을 알려준다. 하지만 월요일 오전엔 무얼했지? 페북에도 쓴 글이 없고, 지메일에도 주고 받은 내역이 없다. 그리고 몇일전에 서버에 노드앱을 추가한게 떠올랐다. 혹시나 싶어 로그를 살펴봤으나.. 젠장 로그에 시간을 안찍어놨네.. 망할… 내일 회사가면 회사 메일을 한번 뒤져봐야겠다. 아~~ 여기까지 추적해왔는데.. 이녀석이 꼬리를 짜르고 도망간 느낌이다. 내 기필코 니놈을 잡고 말테다.
현재, 수사선상의 용의자.
- php-fpm: 그냥 너는 서버를 죽인 실체
- 인도 해커들의 무차별 로그인 공격: 일종의 DDos 공격,… 내가 너무 방어를 안했나? php-fpm에 많은 부하줌.
- 내가 만든 노드 앱들에서 발생하는 메모리 누수(?),.. 모르겠다.
- 그냥 서버 자원이 쪼들려서 그런건가?,..
아무리 생각해도 난 저 계단식 사용률에 문제가 있지 싶다. 그동안 아무런 문제가 없다. 8일부터 특이한 계단식 로그가 찍히는걸봐서는 강력하게 의심이 되는데,.. 그것도 일정하게 증가하는걸로 봐서는… 아! 인도해커들이 일정한 주기로 공격을 하는건가? 아놔 모르겠다.. 일단 자자.