[JEUS] The server shutdown failed and a timeout occurred. shutdown timeout[120000 ms] 원인 분석과 해결방안

 

3줄 요약
- 12월 28일 야간 WAS Shutdown 발생
- 원인 분석
   1) 담당 개발자가 소스 배포 시 수행 스크립트를 잘못 선택
   2) JEUS down, boot 실행 스크립트를 연속 2번 실행 -> JEUS 부팅 중 Timeout으로 인지해 failed 
- 해결 방안 : WAS 재기동 Script 수정

 

 

1. 상황설명

---

12월29일

• 00시경 IDC OP 담당자가 제니퍼 모니터링 중 XX서버 JEUS 인스턴스가 Shutdown 된 것을 확인 후 연락
• 00시 10분 : 원격으로 해당 서버 접속 후 JEUS 확인 및 로그 확인
• 00시 20분 : 해당 서버 ANT 로그 확인 및 ANT 스크립트 확인

 

* JEUS 확인 : 2번 서버 프로세스 failed 상태 확인

ps -ef |grep jeus | grep -v grep : 프로세스 상에 JEUS가 떠있는지 확인.
${JEUS DIR PATH}/bin/dsa         : JEUS 7.0 이후 dsa 스크립트 만들어 사용
   > si                          : 실행중인 컨테이너 상태 확인 명령어
   > application-info            : 실행중인 어플리케이션 상태 확인 명령어

 

 

* 로그 확인 : 로그 내용 중 failed 문구 확인

cd ${LOG DIR PATH}
cat JEUS_SERVER_XXXX.log  또는 tail -f JEUS_SERVER_XXXX.log

 

 

* ANT 로그 확인 결과 : JEUS Boot Failed 출력 문구 확인

* ANT 수행 스크립트 확인 결과 : msdown 명령어 수행 후 바로 msboot 명령어를 수행하는 것을 확인

${JEUS DIR PATH}/bin/msdown_xxx
${JEUS DIR PATH}/bin/msboot_xxx
echo "RESTART SUCCESS"

 

 

 

2. 원인분석

---

해당 서비스는 이중화 되어 2개의 리눅스 서버가 있고, 각 서버에 JEUS가 실행 중이며, 클러스터링 되어 업무를 처리하는 형태입니다.

두 서버가 클러스터링되어있어 한 서버가 다운되어도, 다른 서버에서 업무 수행이 가능해 앞서 발생한 이슈도 업무처리는 계속해서 진행되고 있었습니다.

 

 

 

 

현재 발생한 이슈에서 공통적으로 출력되는 문구가 "Boot Failed"인 것을 미루어 JEUS 부팅 시 발생한 에러인 것을 짐작할 수 있었습니다. 추가적인 원인분석을 위해 형상관리를 확인했고, 해당일에 야간배포가 이뤄진 것을 확인했습니다. 해당 건에 대해 개발자에게 문의해보니 배포 완료 후 각 서버에서 JEUS 재기동 쉘 스크립트를 선택할 때 1, 2번 서버를 선택해야 하는데 2번 서버를 연속해서 선택했던 것을 확인했고, 이로 인해 2번 서버 JEUS의 down, boot 스크립트가 연속 2번 실행되었음을 알 수 있었습니다.

 

 

 

 

하지만 2번 연속으로 수행되었다면, 첫번째 재기동이 완료되고, 두 번째 재기동이 완료되어 Running 상태여야 하는데 왜 Failed 상태로 있었던 건지 이해가 되질 않았습니다. 그래서 시간 순서대로 로그를 다시 정리해 보자 생각해 다음과 같이 정리하게 되었습니다.

2023.12.28 22:08:24 : The JEUS server is SHUTTING DOWN.
2023.12.28 22:08:44 : Unable to shutdown the server in the state STARTING
2023.12.28 22:08:46 : The JEUS server is STARTING
2023.12.28 22:09:48 : The JEUS server is RUNNING

2023.12.28 22:10:44 : The server shutdown failed and a timeout occurred. shutdown timeout[120000 ms]
2023.12.28 22:10:44 : The server has been shut down.
2023.12.28 22.:10:44 : The JVM process is shutting down.
2023.12.28 22:10:44 : The connection has been closed.

 

우선, 눈에 띈 부분은 Unable to shutdown the server in the state STARTING 부분으로, 재기동 중에 'shutdown' 명령어를 입력받아 JEUS에서 해당 로그를 찍은 것으로 유추할 수 있었습니다.

 

이후 중요하게 생각된 부분은 'a timeout occurred' 부분으로 타임아웃이 발생할 이유가 없는데 로그에 기록된 것이 의아하게 생각했습니다. 타임아웃이 발생했다면 어딘가 타임아웃 시간을 설정했을 거라 생각했고, JEUSMain.xml 에서 부팅 시 타임아웃 설정이 12000ms 인 것을 확인했습니다. 또한, 로그에 'The JEUS Server is STARTING' 가 기록된 시간과 'a time out'가 기록된 시간 차를 계산해 보니 120000 ms 값과 유사한 것을 알 수 있었습니다.

 

이를 통해 유추해본 원인은 다음과 같습니다.

 

 

 

 

JEUS 부팅 중에 연속으로 재기동 명령어가 들어오면 JEUS 서버가 Running 상태라도, Timeout이 발생한다.

 

위 조건을 직접 테스트 해보기 위해, 개인 서버에 이슈가 생긴 서버와 동일하게 재기동 스크립트를 작성하고, 연속으로 쉘을 수행한 결과 동일하게 JEUS 서버가 STARTING 후 2분 뒤에 Failed 상태로 접어든 것을 확인할 수 있었습니다.

 

 

 

 

 

3. 해결방안

---

앞선 로그분석을 통해 원인을 추측했고, 테스트를 진행해 동일한 결과를 도출했기에, 최종적으로 해당 서버의 재기동 쉘스크립트만 수정하면 됩니다. 

기존 스크립트 문제점
1) JEUS down과 boot 명령어가 연속으로 수행됨 -> 추후 연속된 명령어는 재기동이 안될 수 있는 문제점 존재
2) 클러스터링 되어있는 서버 순차 재기동이 아닌 일괄 재기동

스크립트 개선점
1) timesleep을 통한 재기동 시간 감안하여 기동 수행되도록 개선
2) 클러스터링 되어있는 서버간 순차 재기동되도록 개선

 

sleep 20

for i in 1 2 3 4 5
do

PS_CNT=`ps -ef | grep "java -D${ServerName}" | grep -v grep | wc -l | tr -d " "`
MS_CNT=echo server-info -server ${ServerName} | ${JEUS DIR PATH}/bin/dsa | grep RUNN | wc -l | tr -d " "`

	if [ ${PS_CNT} -eq 1 ] && [ ${MS_CNT} -eq 1 ]
	then
		echo "RESTART SUCCESS"
		exit
	else
		sleep 20
	fi

done

echo "RESTART FAIL"

 

이상 정리 끝!