[Node.js] winston과 pm2; 502 Bad Gateway

2023년 연말까지 간단한 테스트 서비스를 개발하고 운영에 대비하기 위해 다음을 수행하였다.

1. 선배포와 ci/cd 환경 세팅
2. jmeter 부하 테스트
3. winston 모듈로 카카오 로그인 및 생성 로그 확인

1번은 개발 이전에 수행하였고 2, 3번은 개발이 어느 정도 마무리된 후에 시도하였다.

문제는 3번에서 서버 실행과 데이터 생성 감지 로그를 추가하면서 발생하였다.
사실 해결하고보니 멍청 이슈이긴한데.. 여러 로그 뜯어보면서 알게된 내용들을 기록하려고 한다.

winston 추가 이전

pm2 start index.js -i max --watch 를 통해 클러스터 모드와 파일 변동 감지를 옵션으로 실행하였다.
winston 모듈을 추가하기 이전까지 서버는 문제없이 잘 돌아갔다.
물론 코어 하나 스레드 하나인 서버라 클러스터 모드는 의미가 없었다.
서버비 지원해주세요...

winston 추가 이후

pm2 start index.js -i max --watch 로 실행됐을 때 502 Bad Gateway와 함께 아래의 에러들을 마주했다.

$ sudo pm2 logs

[TAILING] Tailing last 15 lines for [all] processes (change the value with --lines option)
/root/.pm2/pm2.log last 15 lines:
PM2        | 2024-01-01T16:37:28: PM2 log: App name:. id:0 disconnected
PM2        | 2024-01-01T16:37:28: PM2 log: App [.:0] exited with code [0] via signal [SIGINT]
PM2        | 2024-01-01T16:37:28: PM2 log: App [.:0] starting in -cluster mode-
PM2        | 2024-01-01T16:37:28: PM2 log: App [.:0] online
PM2        | 2024-01-01T16:37:28: PM2 log: App name:. id:0 disconnected
PM2        | 2024-01-01T16:37:28: PM2 log: App [.:0] exited with code [0] via signal [SIGINT]
PM2        | 2024-01-01T16:37:28: PM2 log: App [.:0] starting in -cluster mode-
PM2        | 2024-01-01T16:37:28: PM2 log: App [.:0] online
PM2        | 2024-01-01T16:37:28: PM2 log: App name:. id:0 disconnected
PM2        | 2024-01-01T16:37:28: PM2 log: App [.:0] exited with code [0] via signal [SIGINT]
PM2        | 2024-01-01T16:37:28: PM2 log: App [.:0] starting in -cluster mode-
PM2        | 2024-01-01T16:37:28: PM2 log: App [.:0] online
PM2        | 2024-01-01T16:37:29: PM2 log: App name:. id:0 disconnected
PM2        | 2024-01-01T16:37:29: PM2 log: App [.:0] exited with code [0] via signal [SIGINT]
PM2        | 2024-01-01T16:37:29: PM2 log: Script ${PATH} had too many unstable restarts (16). Stopped. "errored"

요약하자면 pm2가 해당 서비스를 errored로 전환해서 생긴 문제였다.

원인 분석

먼저 node index.js로 실행하여 잘 돌아가는 걸 보고 코드 자체에는 문제가 없음을 확인했다.

위의 로그를 확인해보면 문제는 잦은 서버 재시작으로 online 상태에서 errored 상태로 전환되는 것이다.

- 서버가 왜 재시작되는가?

내부 변경 사항이 있으면 재시작될 것이다. 추가로 --watch 옵션을 켜두었으니 중지해도 변동이 발생하면 자동으로 재시작된다.

- winston 모듈 추가 전후 차이는?

서비스에 winston 모듈을 추가와 함께 달라진 점은 /log/<날짜>.log 파일에 필요한 로그를 생성한다는 점이었다.

그래서 결국 문제는

pm2 start index.js -i max --watch로 서버 실행
➡️ 로그 파일에 서버 실행 로그 생성
➡️ --watch 옵션에서 로그 파일의 수정 감지
➡️ 서버 재시작

🔂 무한 반복

해결

sudo pm2 start . --watch --ignore-watch="log/*"
서버 자동 재시작 옵션에서 log 폴더의 변동 사항은 무시하도록 설정해주었다.

index.js에서 .로 바뀐 이유는 혹시 다른 원인일까 찾는 과정에서 바뀌었을 뿐 이 문제와는 관련이 없다.

여기서 헷갈리지 말아야할 점은 --watch는 프로세스가 중지되었을 때도 파일 변동으로 자동 재시작을 지원하는 옵션이라는 점이다.

⚠️ pm2는 서비스가 실행 중일 때 파일 변동 사항이 생기면 자동 재시작을 지원하기 때문에 sudo pm2 start . 처럼 --watch를 제거한다고 문제가 해결되지 않는다.
--ignore-watch="log/*" 를 추가해주는 게 핵심이다.

멍청 이슈였던만큼 빨리 깨달았으면 좋았겠지만 그러지 못했다.
로그 생성이 서버 재시작에 영향을 주지 않도록 주의하자ㅠ

➕ 사용 중에 다른 원인으로 발생할 수 있는 pm2 + 502 에러 해결 방법

• pm2 start <파일명> 대신 <폴더 경로> 사용하기
• yarn start로 실행하기
• SElinux 문제