수집 중에 가끔 시간 초과가 났다. 하루 두세 번이다.
같은 조건으로 다시 돌리면 잘 된다. 재현이 안 되니 고쳐도 고쳐졌는지 알 방법이 없었다.
Table of contents
Open Table of contents
발생할 때의 정보를 남겼다
재현을 못 하니 발생 순간의 정보를 모으기로 했다.
except TimeoutError as e:
log.error(
"timeout device=%s size=%d elapsed=%.1f "
"conn_age=%.0f retry=%d hour=%d",
device_id, len(payload), elapsed,
time.time() - conn_created, retry_count,
datetime.now().hour
)
raisedevice_id 와 자료 크기와 걸린 시간에 더해 연결이 만들어진 뒤 지난 초와 재시도 횟수와 시각을 함께 적는다. 당장 원인을 몰라도 상관있어 보이는 것을 다 남겼다.
무엇이 원인인지 모르면 무엇을 재현해야 하는지도 모른다. 그래서 TimeoutError 를 잡는 자리에 다 적어 두고 며칠을 기다리는 쪽으로 갔다.
일주일치를 모아 봤다
일주일 뒤에 건수부터 셌다.
$ grep "timeout device" collect.log | wc -l
1919건이었다. 그다음 항목별로 분포를 봤다.
$ grep -o "hour=[0-9]*" collect.log | sort | uniq -c
1 hour=2
14 hour=3
3 hour=4
1 hour=9hour=3 에 열네 건이 몰려 있다. 연결 나이도 봤다.
$ grep -o "conn_age=[0-9]*" collect.log | sort -n | tail -5
conn_age=3580
conn_age=3591
conn_age=3598
conn_age=3601
conn_age=3612conn_age 가 3600 근처에 붙어 있었다. 한 시간이다.
한 건씩 볼 때는 아무것도 아니던 숫자가 열아홉 건을 늘어놓으니 hour 와 conn_age 두 곳에서 치우쳤다. 새로 조사한 것은 없고 uniq -c 로 세기만 했다.
원인 — 시각과 연결 나이
치우친 둘을 각각 확인했는데 3시에는 mysqldump 를 부르는 백업 배치가 돌고 있었다.
연결 나이 쪽은 상대 서버가 한 시간 유휴 연결을 끊는 설정이었다. 우리는 그것을 모르고 같은 연결을 계속 들고 있었다.
원인이 하나가 아니라 둘이었고 백업 시간에 응답이 느려지는 것과 conn_age 가 한 시간을 넘어 끊기는 것이 겹쳐 있었다.
둘 다 시간 초과라는 같은 증상으로 나온다. 하나만 고치고 끝냈으면 건수가 줄기만 하고 계속 났을 것이다.
재현하는 방법을 찾았다
원인을 짐작하고 나니 재현이 됐다.
conn = connect()
time.sleep(3700) # 한 시간 넘게 대기
conn.send(data) # 여기서 실패한 시간을 기다리는 것이 오래 걸려서 시험 서버에서는 상대 쪽 유휴 시간 설정을 짧게 바꿔 확인했다.
재현부터 하려던 것이 순서가 반대였다. 원인을 알고 나면 재현은 그 원인을 만들어 주기만 하면 되는 일이 된다.
조치 — 연결을 오래 안 들고 있기
상대가 끊기 전에 우리가 정리하게 했다.
MAX_CONN_AGE = 1800 # 30분
def get_conn():
global _conn, _conn_created
if _conn and (time.time() - _conn_created) > MAX_CONN_AGE:
_conn.close()
_conn = None
if _conn is None:
_conn = connect()
_conn_created = time.time()
return _connMAX_CONN_AGE 를 상대 쪽 한 시간의 절반으로 잡고 지나면 close 한 뒤 다시 연다. 끊긴 연결을 쓰다가 실패하는 대신 멀쩡할 때 버린다.
keepalive 로 신호를 보내 연결을 살려 두는 길도 있었는데 상대가 그것을 받아 주는지 확인이 안 돼서 간단한 쪽으로 했다.
남는 것을 확인했다
고친 뒤 일주일을 다시 셌다.
$ grep -c "timeout device" collect.log
219건이 2건이 됐다. 남은 둘은 hour=3 이라 백업 쪽 문제였다.
전부 없어지지 않아도 어느 원인이 얼마나 줄었는지는 안다. conn_age 쪽이 열일곱 건이었고 백업 쪽이 둘이었다는 것이 이 숫자로 갈렸다.
고치기 전과 같은 grep -c 로 세는 것이 중요했는데 세는 방법을 같이 바꾸면 줄어든 것이 고친 결과인지 세는 방법 때문인지 모른다.
판단 기준 — 무엇을 남길지
이 일 뒤로 오류를 남길 때 무엇을 같이 적을지를 정했다.
항상 남긴다
대상 식별자
걸린 시간
시각 (시간대 포함)
재시도 횟수
상황에 따라
자료 크기
연결 나이
메모리 사용량
직전 성공 시각원인을 모를 때는 상관있어 보이는 것을 다 남기고 나중에 sort 와 uniq -c 로 분포를 보면 그중 하나가 걸린다.
이번에 conn_age 를 안 남겼으면 3시라는 것만 보고 백업만 고쳤을 것이다. 그러면 열일곱 건이 그대로 남는다.
로그가 없으면 재현을 못 하고 재현을 못 하면 못 고친다. 무엇을 남길지는 문제가 나기 전에 정해 둬야 하는 것이었다.
정리
- 재현이 안 되면 발생 순간의 정보를 모은다
- 원인을 모르면 무엇을 재현할지도 모르므로 자료부터 쌓는다
- 여러 건을 모아 항목별 분포를 보면 치우친 것이 나온다
- 치우친 항목이 둘이면 원인도 둘일 수 있다
- 하나만 고치면 건수만 줄고 증상은 계속 난다
- 원인을 짐작하고 나면 재현은 그 조건을 만들어 주는 일이 된다
MAX_CONN_AGE를 상대의 절반으로 잡아 끊기기 전에 정리한다- 고친 뒤 같은 명령으로 다시 세어 어느 원인이 얼마나 줄었는지 본다
- 오류에 무엇을 남길지를 문제가 나기 전에 정해 둔다