간헐적 500 Server Internal Error 원인 파악하기

구성

Service1.domain.co.kr 에 접속할 경우

Service1.domain.co.kr 도메인의 dns설정은 cname proxy.domain.co.kr(nginx proxy서버) 으로 해놓고

Service1.domain.co.kr > nginx proxy(nginx proxy서버) > server:service1 port(docker)

상황 : 여러 서비스에서 간헐적으로 500 Server internal Error 발생. 새로고침하면 정상화. 새로고침하면 정상화 되기에 서비스 이용에는 크게 문제가 없으나 API 이용시 500 error 발생으로 스크립트 오작동하는경우 발생.

 

사내 모니터링 툴인 icinga2(nagios기반)에서는 에러 발생시 1분뒤 다시한번 체크하도록 설정 돼 있기에 icinga2에서는 서비스 에러 체크가 안돼고 있었음.
다만 debug 모드에서는 500 error를 확인 할 수 있다. icinga2로그 확인시 같은시간에 여러 서비스에서 동시에 발새하는것으로 보아 어플리케이션 단일의 문제는 아닐것으로 보인다.

 

그럼 서비스들이 모여있는 web1, 또는 intra1 그리고 DB서버, proxy 정도의 문제로 의심해볼 수 있을듯 하다. 여기서 확인해볼 수 있는것은 최종 목적지인 web1, intra1 모든 서버에서 에러가 발생하고 있고 특히 xlsoft의 경우 디비 설정도 안돼있기에 디비 문제도 아님이 확인된다.

proxy0에 있는 munin, icinga2 는 에러가 없는것으로 보아 proxy1 서버에서 발생하는 문제라 추측하고 원인 파악할 예정

우선 접속자가 가장 적은 test.co.kr 을 모니터링 할꺼고 1.1.1.1(proxy1)과 통신을 전혀 하지 않는 standby1에서 tcpdump를 뜬다. 그래야 딱 test.co.kr 꺼만 tcpdump가 가능하니까

#!/bin/bash
function check_fnc(){
CMD=`docker exec -it compose.icinga2.test.co.kr /usr/lib/nagios/plugins/check_http -I 1.1.1.1 -S -u <https://www.test.co.kr/images/xlsoftlogo.png`>
CRI=`echo $CMD | awk '{print $2}'`
date > /etc/bin/date.txt
}

check_fnc
while [ $CRI != "CRITICAL:" ]
do
check_fnc
sleep 2
done

위 스크립트를 돌려놓기.

tcpdump 떠놓고 위 스크립트로 500 error 발생할 때까지 스크립트 돌려놓기

1) 11:24:11.764227 IP standby1.58272 > 1.1.1.1.https: Flags [S], seq 1285422234, win 29200, options [mss 1460,sackOK,TS val 2345513401 ecr 0,nop,wscale 9], length 0
2) 11:24:11.764640 IP 1.1.1.1.https > standby1.58272: Flags [S.], seq 3917766911, ack 1285422235, win 28960, options [mss 1460,sackOK,TS val 2362302169 ecr 2345513401,nop,wscale 9], length 0
3) 11:24:11.764706 IP standby1.58272 > 1.1.1.1.https: Flags [.], ack 1, win 58, options [nop,nop,TS val 2345513401 ecr 2362302169], length 0
4) 11:24:11.766695 IP standby1.58272 > 1.1.1.1.https: Flags [P.], seq 1:280, ack 1, win 58, options [nop,nop,TS val 2345513403 ecr 2362302169], length 279
5) 11:24:11.766881 IP 1.1.1.1.https > standby1.58272: Flags [.], ack 280, win 60, options [nop,nop,TS val 2362302208 ecr 2345513403], length 0
6) 11:24:11.769720 IP 1.1.1.1.https > standby1.58272: Flags [.], seq 1:5793, ack 280, win 60, options [nop,nop,TS val 2362302211 ecr 2345513403], length 5792
7) 11:24:11.769838 IP standby1.58272 > 1.1.1.1.https: Flags [.], ack 5793, win 80, options [nop,nop,TS val 2345513406 ecr 2362302211], length 0
8) 11:24:11.769977 IP 1.1.1.1.https > standby1.58272: Flags [P.], seq 5793:6028, ack 280, win 60, options [nop,nop,TS val 2362302211 ecr 2345513403], length 235
9) 11:24:11.770009 IP standby1.58272 > 1.1.1.1.https: Flags [.], ack 6028, win 86, options [nop,nop,TS val 2345513406 ecr 2362302211], length 0
1) 011:24:11.770843 IP standby1.58272 > 1.1.1.1.https: Flags [P.], seq 280:406, ack 6028, win 86, options [nop,nop,TS val 2345513407 ecr 2362302211], length 126
11) 11:24:11.800062 IP 1.1.1.1.https > standby1.58272: Flags [P.], seq 6028:6079, ack 406, win 60, options [nop,nop,TS val 2362302241 ecr 2345513407], length 51
12) 11:24:11.800284 IP standby1.58272 > 1.1.1.1.https: Flags [P.], seq 406:553, ack 6079, win 86, options [nop,nop,TS val 2345513437 ecr 2362302241], length 147
13) 11:24:11.818999 IP 1.1.1.1.https > standby1.58272: Flags [P.], seq 6079:6433, ack 553, win 62, options [nop,nop,TS val 2362302260 ecr 2345513437], length 354
14) 11:24:11.819120 IP 1.1.1.1.https > standby1.58272: Flags [FP.], seq 6433:6464, ack 553, win 62, options [nop,nop,TS val 2362302260 ecr 2345513437], length 31
15) 11:24:11.819208 IP standby1.58272 > 1.1.1.1.https: Flags [.], ack 6465, win 91, options [nop,nop,TS val 2345513456 ecr 2362302260], length 0
16) 11:24:11.819235 IP standby1.58272 > 581.1.1.1.https: Flags [F.], seq 553, ack 6465, win 91, options [nop,nop,TS val 2345513456 ecr 2362302260], length 0
17) 11:24:11.819447 IP 1.1.1.1.https > standby1.58272: Flags [.], ack 554, win 62, options [nop,nop,TS val 2362302261 ecr 2345513456], length 0

이게 500 에러일 때 tcpdump

1) 16:14:47.778543 IP standby1.42750 > 1.1.1.1.https: Flags [S], seq 387201813, win 29200, options [mss 1460,sackOK,TS val 2276549415 ecr 0,nop,wscale 9], length 0
2) 16:14:47.778893 IP 1.1.1.1.https > standby1.42750: Flags [S.], seq 1673702661, ack 387201814, win 28960, options [mss 1460,sackOK,TS val 2293338207 ecr 2276549415,nop,wscale 9], length 0
3) 16:14:47.778973 IP standby1.42750 > 1.1.1.1.https: Flags [.], ack 1, win 58, options [nop,nop,TS val 2276549415 ecr 2293338207], length 0
4) 16:14:47.781420 IP standby1.42750 > 1.1.1.1.https: Flags [P.], seq 1:280, ack 1, win 58, options [nop,nop,TS val 2276549418 ecr 2293338207], length 279
5) 16:14:47.781666 IP 1.1.1.1.https > standby1.42750: Flags [.], ack 280, win 59, options [nop,nop,TS val 2293338210 ecr 2276549418], length 0
6) 16:14:47.783826 IP 1.1.1.1.https > standby1.42750: Flags [P.], seq 1:6028, ack 280, win 59, options [nop,nop,TS val 2293338212 ecr 2276549418], length 6027
7) 16:14:47.783933 IP standby1.42750 > 1.1.1.1.https: Flags [.], ack 6028, win 81, options [nop,nop,TS val 2276549420 ecr 2293338212], length 0
8) 16:14:47.785036 IP standby1.42750 > 1.1.1.1.https: Flags [P.], seq 280:406, ack 6028, win 81, options [nop,nop,TS val 2276549421 ecr 2293338212], length 126
9) 16:14:47.785568 IP 1.1.1.1.https > standby1.42750: Flags [P.], seq 6028:6079, ack 406, win 59, options [nop,nop,TS val 2293338214 ecr 2276549421], length 51
10) 16:14:47.785670 IP standby1.42750 > 1.1.1.1.https: Flags [P.], seq 406:553, ack 6079, win 81, options [nop,nop,TS val 2276549422 ecr 2293338214], length 147
11) 16:14:47.788991 IP 1.1.1.1.https > standby1.42750: Flags [P.], seq 6079:10659, ack 553, win 61, options [nop,nop,TS val 2293338217 ecr 2276549422], length 4580
12) 16:14:47.789028 IP 1.1.1.1.https > standby1.42750: Flags [FP.], seq 10659:10690, ack 553, win 61, options [nop,nop,TS val 2293338217 ecr 2276549422], length 31
13) 16:14:47.789149 IP standby1.42750 > 1.1.1.1.https: Flags [.], ack 10659, win 99, options [nop,nop,TS val 2276549426 ecr 2293338217], length 0
14) 16:14:47.789189 IP standby1.42750 > 1.1.1.1.https: Flags [F.], seq 553, ack 10691, win 99, options [nop,nop,TS val 2276549426 ecr 2293338217], length 0
15) 16:14:47.789349 IP 1.1.1.1.https > standby1.42750: Flags [.], ack 554, win 61, options [nop,nop,TS val 2293338218 ecr 2276549426], length 0

이건 정상일 때 tcpdump

1. SYN-SENT - standby1에서 proxy1로 Syn을 보냄 : 내가(standby1) 너(proxy1)한테 접속 해도 돼 ?
2. SYN-RECEIVE - proxy1에서 syandby1한테 Syn에 대한 응답(Ack) : 너(standby1)한테 Syn 잘 받았어 (ACK) 나 준비완료, 들어와도돼 (Syn.), tcpdump에서는 Ack를 .으로 표현
3. ESTABLISHED - standby1에서 proxy1로 Ack 보냄 : 나(standby1) 랑 너(proxy1) 연결됐어 1~3까지가 3WAY 핸드쉐이크
4. SSL 핸드쉐이크 부분 - https://run-it.tistory.com/29 이거나 https://lxxyeon.tistory.com/176 이거를 4~9 까지 요거 참고
5. SSL 핸드쉐이크 부분 - https://run-it.tistory.com/29 이거나 https://lxxyeon.tistory.com/176 이거를4~9 까지 요거 참고
6. SSL 핸드쉐이크 부분 - https://run-it.tistory.com/29 이거나 https://lxxyeon.tistory.com/176 이거를4~9 까지 요거 참고
7. SSL 핸드쉐이크 부분 - https://run-it.tistory.com/29 이거나 https://lxxyeon.tistory.com/176 이거를4~9 까지 요거 참고
8. SSL 핸드쉐이크 부분 - https://run-it.tistory.com/29 이거나 https://lxxyeon.tistory.com/176 이거를4~9 까지 요거 참고
9. SSL 핸드쉐이크 부분 - https://run-it.tistory.com/29 이거나 https://lxxyeon.tistory.com/176 이거를4~9 까지 요거 참고
10. SSL 암호화된 데이터 전송 https OK
11. SSL 암호화된 데이터 전송 https OK
12. FIN_WAIT1 - proxy1에서 standby1한테 접속 끊자는(FIN) 패킷 발송 : 나(proxy1)는 너(standby1)한테 볼일 다 봤어. 이제 끊자(FIN)
13. CLOSE_WAIT - standby1이 proxy1한테 Fin에 대한 응답(Ack) : 그럴래 ? 잠깐만~ 너가 볼일 다본 프로세스 종료준비좀 할께. 기다려봐
14. LAST_ACK - standby1이 proxy1한테 FIN 패킷 발송 : 나(standby1)는 프로세스 종료할 준비 됐어 ~ 너 준비 됐어 ?
15. TIME_WAIT - proxy1이 standby1한테 종료에 대한 응답 .(ACK) 발송 : 응. 나 끊었어
    끝

정상 / 비정상과 딱히 차이 없음.

비정상일때 패킷2개가 더 있긴한데 이거는 SSL 통신할 때 인증서 확인을 한패킷에서 했냐 한번 나눴냐 차이. 즉 패킷이 끊기는건 없다. 따라서 timeout은 아니라는 말.
ㄴ간헐적 장애는 거의 대부분이 timeout문제(경험)임. 네트워크랑 앤드포인트나 애플리케이션단 타임아웃이 서로 달라서 발생하는등. 근데 이 문제는 타임아웃 문제 아님. 그럼 백프로 nginx proxy서버문제가 맞다고 보여진다.

nginx proxy 에러로그를 다시한번 살펴보면..

에러 발생한 시간에 bind(0.0.0.0) failed (98: Address already in use) while connecting to upstream, 이게 찍혀있다. 포트 중복되는 문제로 많이 보던 에러라 보고서 누가 포트 잘못 올렸나 하고 넘어갔떤건데... 이제보니 포트가 안찍혀있다.
그리고 생각해보면 포트 중복문제면 nginx 재시작등 서비스 올라올 때 포트 중복되면 찍혀야 하는건데 이건 라이브중에 찍힌 에러.. 이 에러가 문제가 맞는것으로 보인다.

혹시나 icinga2에서 에러 발생한 시간에 맞춰보니 전부 그시간에 위 에러가 찍혀있다. 물론 icinga2는 체크를 실시간으로 하는게 아니니까 백프로 일치하진 않지만 nginx에 찍힌 에러 로그안에 아이싱가 로그 시간을 포함하고 있다.

bind(0.0.0.0) failed (98: Address already in use) while connecting to upstream 이처럼 포트가 안찍히는 경우는 해당 서버가 클라이언트입장에서 서버로 로그인 할 때 클라이언트 포트가 이미 사용중이라 해당 에러가 발생할 수 있다. > nginx proxy가 실서비스(도커의 :28080)

 

[root@proxy1 ~]# cat /proc/sys/net/ipv4/ip_local_port_range

1024 65535

[root@proxy1 nginx]# netstat -an |grep TIME_WAIT | grep -v 1.1.1.1:443 | grep -v 1.1.1.1:80 | awk '{print $4}'| awk -F ":" '{print $2}' | sort -n | head

1024

1025

1026

1027

1030

[root@proxy1 nginx]# netstat -an |grep TIME_WAIT | grep -v 1.1.1.1:443 | grep -v 1.1.1.1:80 | awk '{print $4}'| awk -F ":" '{print $2}' | sort -n | tail

65524

65525

65528

65529

65535

[root@proxy1 nginx]# netstat -an |grep TIME_WAIT | grep -v 1.1.1.1:443 | grep -v 1.1.1.1:80 | wc -l 44562

실제로 클라이언트 포트를 1024부터 뛰엄뛰엄 65535까지 상당히 많이 쓰고 있지만 이론상으로 현재 문제는 발생하면 안된다.(6만개도 안넘었으니까)

[root@proxy1 log]# cat /home/var/proxy1.datawave.co.kr/logs/error.log | grep 'Address already in use' | awk '{print $2}' | awk -F ":" '{print $1":"$2}' | sort | uniq -c | sort -rn | head -n 100

10743 05:29

10472 05:28

10092 05:43

10070 06:29

8481 05:51

8263 05:49

8252 05:48 중략

6081 05:26

6065 05:08

새벽 5~6시에 집중돼있음

netstat -an 카운트 새벽에 계속 돌렸을 때 몇개까지 차는지 보면 이게 원인인지 아닌지 확인 할 수 있음

만약 클라이언트 포트 고갈 문제가 맞다면

log3의 8080(fastlog)와 통신을 가장 많이하는데 이거 1회성 연결로 끊지말고 1시간에 한번씩 연결해서 작업하던가 하는 식으로 바꾸는게 바람짐학

서버에서 해줄 수 잇는 작업은 리싸이클 커널 파라미터 조정해야 할 듯 한데(그 외 커널 파라미터는 최적화 돼 있는 상태임)

https://m.blog.naver.com/PostView.naver?isHttpsRedirect=true&blogId=nkyle9361&logNo=220060056557

근데 위 설정 해주면 fin 안받고 세션 끊고 바로 배정하는거라 킵얼라이브처럼 세션 재활용할 때 500 에러 난다고 하니 위 설정은 하면 안될 듯 - 위 본문에도 있듯이 Client쪽이 방화벽 또는 NAT 환경일 때<< 프록시 서버라 문제 날 수 있을것같음.