Sign in Subscribe
pm2

pm2 + log4js

Seonho Jeong

• 5 min read


pm2에서 여러 프로세스를 띄우고 log4js를 같이 사용하면서 발생한 문제점과 해결책에 대해 기술한다.

pm2

대부분 시스템은 이제 k8s 환경에서 관리되는데, 그전에는 nodejs를 pm2로 관리하고 있었다. 프로세스 failover, 무중단 배포, 클러스터링, 로깅, 모니터링 등을 지원한다. (거의 k8s 아닌가 싶다)


k8s 아닌가 싶은 생각, 기능이 겹치지 않냐 하는 측과
pm2를 k8s 환경에서 띄웠을 때 가져갈 수 있는 장점이 있다는 측의 수많은 논의들이 웹상에서 이루어지고 있다.
즉, k8s에서 pm2를 가져가 말아 하는 논의인데 검색하다보면 보는 재미가 쏠쏠하다.

여튼, 현재 시스템은 아직 k8s 환경이 아니고, pm2를 통해 배포 및 클러스터링, 로깅을 가져가고 있다.

log4js
spring에도 로깅에는 log4j, log4j2, logback 등 여러 라이브러리가 있듯이
nodejs에도 여러 라이브러리가 있다. 대표적으로 log4js, winston, pino가 있는데 그 중 log4js가 가장 성능이 낮고 기능도 별로 없지만(있을건 있다!), 가장 적용하기 쉽다는 장점이 있다.
큰 트래픽을 감당할 시스템도 아니고, 복잡한 로그 기능이 필요하지 않아 해당 라이브러리를 채택.

log4js(with pm2)

이 조합은 그 동안 문제 없었다. log4js에서도 https://log4js-node.github.io/log4js-node/clustering.html 해당 옵션을 통해 pm2를 지원하고 있고 별 문제 없이 로그는 잘 쌓여왔었다.

log4js와 pm2를 같이 쓰는 방법

pm2에는 Master 프로세스가 없고 모두 worker 프로세스 (https://github.com/log4js-node/log4js-node/issues/265#issuecomment-331090803)
=> Log4js 는 쓰기 할 프로세스가 없으니 로깅이 제대로 안됨
=> 그래서 log4js에 pm2 설정을 주면 pm2 id: 0인 프로세스를 마스터로 취급함 (https://github.com/log4js-node/log4js-node/blob/master/lib/clustering.js#L20)

근데 그래도 pm2 에서는 id : 0 마스터 프로세스만 제대로 로깅하고 나머지 프로세스들은 로그가 안찍히는 현상 발생
=> pm2-intercom을 통해 프로세스간 메시지 송수신을 활성화

pm2 환경에 여러 process를 띄워놓고 log4js를 통해 단일 파일에 쓰기를 할 경우
log4js에서는 pm2의 0번 process를 마스터로 지정해야하고
pm2-intercom을 통해 프로세스간 메시지 송수신을 추가로 활성화 해야한다.

문제 발생

  1. 여러 API가 동시에 호출
  2. 네트워크 계층의 로드밸런서가 서로 다른 서버로 보내거나, pm2 로드밸런서가 서로 다른 프로세스로 라우팅
  3. 여러 로그가 같은 시간대에 섞여서 출력
  4. 하나의 요청에 대해 시간순으로 보기 어려움

위 이슈를 해결하기 위해 node의 AsyncLocalStorage API 활용
그에 더해 로그에 더 많은 context(요청 id, 요청 유저 id 등...)를 동적으로 넣는 log4js 설정 적용했으나, 로그에 제대로 담기지 않는다 (없거나, 다른 id)


문제 분석


log4js가 tokens를 언제 호출하는지 확인 필요.

ref: log4js 코드
log4js는 node의 클러스터링을 지원하기 위해 현재 프로세스가 master 프로세스인지 worker 프로세스인지 확인. master 프로세스만 메시지 로깅 수행, worker 프로세스는 master 프로세스에게 로그 메시지 전송.

master 프로세스에게만 쓰기를 맡기는 이유를 추측해보면
=> log4js의 파일 쓰기는 기본적으로 비동기 (node의 file write stream을 통해 쓰기)
=> 여러 프로세스가 같은 파일에 비동기로 쓰기를 할 수는 없으니
=> 한 프로세스에게 역할을 맡기고 해당 프로세스만 파일 쓰기

의심점

마스터 프로세스에서 tokens 함수(log4js 동적 값 로깅)를 수행할 때
worker 프로세스에서 온 로깅 이벤트라면
token을 동적으로 주입할 때 request context를 제대로 찾지 못하는거 아닐까?
(master process가 메시지를 받아서 언제 tokens 함수를 호출하는지는 파악하지 못함)

const configure = {
  appenders: {
    date: {
      type:'dateFile',
      filename: 'app.log'
      pattern: '.yyyy-MM-dd',
      layout: {
        type:'pattern',
        pattern: `... (%x{requestId}) (%x{userId}) %m`,
        tokens: {
          requestId: () => {},
          userId: () => {}
        }
      }
    }
...

해결방법

각 프로세스별 로그 파일을 따로 관리하고, 각 프로세스는 자신이 master 프로세스인거 처럼 직접 로그를 남긴다.

filename: app-{process.pid}.log
pm2: true
disableClustering: true

근본적인 해결책(pm2당 하나의 파일에 로깅)은 아니지만, 별도의 로그 수집기(ELK)를 같이 배포했다면 여러 파일로 나뉘어도 상관없다.

Sign up for more like this.

Enter your email
Subscribe