[개발 일지] 간헐적 502에러 해결기

기존 블로그에서 옮겨온 글입니다. (21/7/15 작성)

처음부터 주어진 과제

크래프타에서 일하게 되면서 TMM의 개선점을 분석해 오라는 요청을 받게 되었습니다.
이것저것 둘러보면서 사이트를 분석하던 중 불특정한 주기로 502에러가 나타나는 것을 확인할 수 있었습니다.

개선점 분석 내용을 발표하면서 이에 대해 말씀드렸더니 대표님께서 사실 꽤 오래 전부터 해결하려고 했으나 원인을 밝히지 못했다고 말씀해주셨습니다.

그렇게 첫 날부터 저의 to-do list에 502해결하기가 자리잡게 되었습니다.

알 수 없는 자신감

왠지 모르게 해결할 수 있을 것 같다는 자신감을 가지고 apache 로그부터 분석하기 시작했습니다. 그런데 특이하게도 apache access log에서 response code를 살펴본 결과 502가 발견되지 않았습니다.

그렇다면 발생할 수 있는 구간이 어디가 있을지 생각해보던 중 ELB와 EC2 인스턴스 간의 연결을 의심해보게 되었습니다.
실제로 aws 문서를 찾아보던 중 elb와 ec2 인스턴스 간 통신이 끊어지면서 502가 발생할 수 있다는 글을 보게 되고 의심은 더욱 깊어져 갔습니다.

다음으로는 apache error log를 살펴봤습니다.
그런데 특이하게도 주기적으로 동일한 에러로그가 찍히고 있는 것을 확인했습니다.

(현재는 해당 서버구조를 이용하지 않고 있으므로 첨부합니다.)

나름대로 이 로그에 대해 해석해본 결과는 다음과 같습니다. apache에서 virtual hosting에 관여하는 mpm_itk라는 모듈이 있습니다. 해당 모듈에서는 setgid 함수를 통해 주기적으로 gid를 변경하게 됩니다. 하지만 이 과정에서 알 수 없는 오류로 operation not permitted가 떴고 이로 인해 apache가 connection을 종료해버린다고 파악했습니다.

 

조금 더 확신을 가지기 위해 ELB 로그도 분석해본 결과 502 코드를 반환하는 response의 경우 백엔드에서 돌아온 상태코드가 존재하지 않았고(-) 소요 시간도 없는 것으로 나왔습니다.

 

저는 mpm_itk의 setgid 실패가 elb와 ec2 인스턴스 사이의 연결을 끊는 것이 502의 원인이라는 가설을 세우고 이를 해결하기 위해 (늘 그렇듯) 검색을 하기 시작했습니다.

아무리 찾아도 나오지 않는 해결책

오류 코드가 명확했음에도 불구하고 생각보다 비슷한 에러를 겪은 사람들이 많지 않았습니다.

결국 한참을 찾다가 일단 묻어두고 다른 작업을 먼저 처리하기로 했습니다.

 

얼마가 지난 후 다시 에러 코드를 바탕으로 검색을 해보던 중 특이한 것을 발견했습니다.
다른 사람들이 올려놓은 로그를 보니 모두 하나같이 uid와 gid가 일치하는데 TMM 로그의 경우에는 uid와 gid가 1차이가 나는 것이었습니다.

실제로 mpm_itk 모듈의 사용법을 살펴본 결과 AssignUserId 라는 property에 username과 groupname을 입력하는데 일반적으로 둘을 같도록 설정하는 것 같았습니다.
하지만 TMM 본서버의 apache 설정에서는 AssignUserId에 서로 번호가 다른 username과 groupname이 설정 되어있는 것을 확인했습니다.

 

저는 여기서 uid와 gid가 다른 상태로 setgid 함수를 호출했고 그 결과 호출한 user와 group이 일치하지 않아 권한이 없다는 오류가 떴을 것이라는 두 번째 가설을 세우게 됐습니다.

 

그리고 이를 입증하기 위해 대표님께 AssignUserId 에 대해 같은 username과 groupname을 설정하는 것을 제안드렸습니다.

1차 시도 실패

apache config 파일을 백업해 두고, 동시 접속자 수가 조금 적은 틈을 타 AssignUserId 프로퍼티를 변경하여 apache를 restart 했습니다.

그럼과 동시에 기존에 저장되어 있던 쿠키들의 세션 셋팅과 바뀐 셋팅이 맞지 않아 php 오류가 떴고 일단 급하게 롤백을 진행했습니다.

이후 error log를 분석해봤을 때 uid와 gid가 같음에도 동일한 에러 로그가 찍힌 것을 확인할 수 있었습니다.

재현할 수 있는 방법이 없다

디버깅에서 가장 좋은 방법은 하나씩 변경해가며 해결되는지 확인하는 것이라고 생각합니다.
하지만 이번 502에러의 경우 인프라 셋팅에서 문제가 발생하여 재현자체가 쉽지 않았습니다.

일단 AMI를 통해 동일한 셋팅의 dev 서버를 하나 만들었습니다. 하지만 mpm_itk가 virtual hosting을 위한 모듈이고 dev서버의 경우 호스팅을 두개로 나누는 셋팅 자체가 부담스러워 dev서버를 통한 해결책 분석은 실패로 돌아갔습니다.

 

그렇게 제가 세운 가설이 원인이 맞는지도 확인하지 못한채로 흐지부지 되는 것 같던 중 우연히 ec2의 network interface 주소로 직접 접속하면 무조건 처음 다섯 번 정도 새로고침 할 때까지 502에러가 뜬다는 것을 확인했습니다.

 

저는 여기서 열심히 새로 고침을 하며 의도적으로 에러 로그를 찍었고 시간을 대조한 결과 apache error log의 operation not permitted 가 502에러와 동일한 시간에 발생함을 확인할 수 있었습니다.

2차 시도 성공

이제 원인은 확실히 알았으니 어떻게 하면 해결할 수 있을지 고민하던 중 virtual hosting을 하지만 AssignUserId 값은 셋팅하지 않는 예시들이 많다는 것을 눈치챘습니다.

실제로 mpm_itk 모듈의 document를 읽어보니 이 값을 셋팅하지 않으면 기본 apache user (일반적으로 www-data)로 실행된다는 것을 알 수 있었습니다.

 

www-data로 모든 프로세스가 실행되면 setgid가 일어날 필요도 없고 그러면 자연스럽게 문제가 해결될 수 있겠다는 생각에 대표님께 AssignUserId 프로퍼티 삭제를 제안드렸고 흔쾌히 승낙해주셨습니다.

 

사람이 조금 적은 시간을 틈타 두 번째 시도를 했고 마찬가지로 cache 때문에 에러가 났지만 한 번 경험해보면서 생각해둔 방법대로 cache를 삭제하여 php 오류는 해결할 수 있었습니다.

 

그 후 계속 방치하면서 원래 502에러가 났던 ip주소로도 접속해보고, apache error log도 계속 살펴보고 elb 로그도 살펴본 결과 10분, 20분이 지나도 502가 발생하지 않는 것을 확인할 수 있었습니다.

눈으로 보이는 성공

마지막으로 확바뀐 elb 502 지표 보여드리면서 글 마무리하려고 합니다.

 

일을 시작하고 약 한 달에 걸쳐 해결하려고 매달렸던 오류를 해결하고 나니 더 없이 행복했습니다.
긴 글 읽어 주셔서 감사합니다.