내가 올린 다음 날 오류가 늘었다는 말을 들었다. 되돌릴 준비를 해 두고 내 코드를 두 시간 동안 뒤졌다.
Table of contents
Open Table of contents
언제부터인지 안 물어봤다
두 시간 뒤에야 로그를 날짜별로 세어 봤다. Tomcat 은 JULI FileHandler 로 catalina.YYYY-MM-DD.log 를 날짜마다 만든다. catalina.out 은 로테이션되지 않고 계속 붙기만 한다.
$ grep -c Exception catalina.2011-09-*.log
catalina.2011-09-08.log:31
catalina.2011-09-09.log:28
catalina.2011-09-10.log:35
catalina.2011-09-11.log:33
catalina.2011-09-12.log:41내가 배포한 것은 11일이다. 그 전에도 하루 30건 안팎이 나고 있었다. 늘어난 것이 아니라 원래 있던 것이고, 내가 올린 뒤에 누가 로그를 처음 본 것이었다.
두 시간을 쓴 이유가 언제부터 나는 증상인지를 안 물어봤기 때문이다. 내가 SVN 에 올린 다음 날이라는 말만 듣고 그 전제로 들어갔다.
늘었는지 세는 순서
증상을 들으면 먼저 날짜별로 세어 보기로 했다. grep -c 로 파일마다 예외 수를 세면 언제부터인지가 바로 나온다.
그다음에 어느 종류가 늘었는지 본다. grep -o 로 예외 이름만 뽑아 uniq -c 로 세면 무엇이 늘었는지가 갈린다.
$ grep -o "[A-Za-z]*Exception" catalina.2011-09-12.log | sort | uniq -c | sort -rn
41 NullPointerException
12 SQLException
3 NumberFormatException날짜와 종류를 같이 보면 언제부터 무엇이 늘었는지가 정해진다. 이걸 먼저 하면 SVN 이력을 뒤질지 내 코드를 뒤질지가 갈린다.
원래 있던 것도 봤다
원래 있던 것이라고 넘기지는 않았다. 하루 30건이 나는 자리를 Eclipse 에서 열어 보니 로그인 안 한 사람이 들어올 때 나는 NullPointerException 이었다.
String id = (String) session.getAttribute("userId");
if (id.equals("admin")) { ... }세션에 값이 없으면 id가 비어 있고 거기서 난다. 값을 앞에 두면 비어 있어도 안 난다.
같은 모양이 다른 데도 있는지 찾아보니 64곳이었다. 그중 앞이 변수인 것을 골라 고쳤다. 한 자리만 고치면 다음 주에 다른 자리에서 같은 것이 난다.
로그를 보는 사람이 없었다
하루 30건이 나는데 아무도 모르고 있었다는 것이 더 큰 문제였다. 로그가 쌓이기만 하고 보는 사람이 없었다.
매일 아침에 어제 것을 종류별로 세어서 붙여 두게 했다.
d=$(date -d yesterday +%Y-%m-%d)
grep -o "[A-Za-z.]*Exception" "catalina.$d.log" | sort | uniq -c | sort -rn | head -10숫자가 보이니 늘었는지 줄었는지가 드러난다. crontab 에 걸어 두고 메일로 받는다. 고친 뒤 30에서 3으로 줄어든 것도 이걸로 알았다.
원인이 내 코드가 아니었지만 되돌릴 준비를 해 둔 것 자체는 필요했다. SVN 에 무엇을 올렸는지가 남아 있으면 되돌리는 것이 빠르다. 올릴 때마다 무엇을 바꿨는지 적어 두는 것이 이때 값을 한다.
정리
- 증상을 들으면 언제부터인지 먼저 확인한다
- 늘어난 것과 원래 있던 것은 다르고 뒤지는 자리도 다르다
- 로그를 날짜별로 세고 종류별로도 센다. 둘을 같이 보면 시점이 정해진다
- 늘지 않았어도 나는 것은 나는 것이라 원래 있던 것도 본다
- 변수를 앞에 두고 비교하면 값이 비었을 때 난다. 값을 앞에 둔다
- 한 자리만 고치면 다음에 다른 자리에서 난다. 같은 모양을 전부 찾는다
- 로그를 아무도 안 보면 하루 30건도 모른다. crontab 으로 매일 세어 보이게 둔다
- 원인이 아니었어도 되돌릴 준비를 해 두는 것은 필요하다