TL;DR

winston 라이브러리에서 logger의 transports는 반드시 아래 두 방식으로만 추가해야 합니다.

1. createLogger 메서드에서 인자로 전달
2. logger의 add 메서드로 인스턴스에 전달

logger 인스턴스의 transports 필드에 직접 접근해서 push하면 transport가 연결되지 않습니다.

import winston from "winston";

const logger = winston.createLogger({
      level: "info",
      format: winston.format.simple(),
      defaultMeta: { service: "api-server" },
      // good
      transports: [customTransport1],
    });

// good
logger.add(customTransport2);

// bad
logger.transports.push(customTransport3);

Overview

    회사에서 로그 검색 서비스로 logzio를 사용하고 있습니다. 각종 오류가 발생할 때 추적용도로 자주 사용하는데, 어느 순간부터 로그가 기록되지 않았습니다. 로그 양이 급격하게 줄어든 시점에 어떤 PR이 있었는지 찾아봤더니 winston logger의 설정이 바뀌었습니다.
    기존에는 logzio 서비스로 로그를 보내는 transport를 생성하고 createLogger 메서드에 해당 인스턴스를 전달했는데, 바뀐 버전에서는 logger 인스턴스 transports 필드의 push 메서드(자바스크립트 내장 함수)를 호출해서 추가했습니다. 이 부분에서 뭔가 문제가 발생했다는 것을 알 수 있었습니다.

테스트

실제 테스트코드를 작성해보니, winston logger에서 transports의 push 메서드를 호출해도 transports에는 변화가 없었습니다. 즉, 결과가 아래와 같습니다.

const logger = winston.createLogger({
      level: "info",
      format: winston.format.simple(),
      defaultMeta: { service: "api-server" },
      transports: [],
    });

console.log(logger.transports); // []
logger.transports.push(customTransport)
console.log(logger.transports); // []. 여전히 빈 배열이다.

분석

    왜 push 메서드로는 transport를 추가할 수 없는지 확인하기 위해 winston의 소스코드를 찾아봤습니다. 먼저 winston/lib/winston/logger.js에서 정의하는 Logger 클래스를 보겠습니다. 주석은 생략했습니다.

// winston/lib/winston/logger.js

class Logger extends Transform {
  constructor(options) {
    super({ objectMode: true });
    this.configure(options);
  }

  // 파라미터 생략
  configure({transports, ...options}) {
    // ... 생략 ...
  }
}

    Logger 클래스는 인스턴스를 생성할 때 configure 메서드를 호출합니다. 각종 설정들을 초기화하는 부분입니다. configure 메서드의 transports 관련 부분만 보겠습니다.

    // Reset transports if we already have them
    if (this.transports.length) {
      this.clear();
    }

    // Add all transports we have been provided.
    if (transports) {
      transports = Array.isArray(transports) ? transports : [transports];
      transports.forEach(transport => this.add(transport));
    }

주석에서도 친절히 설명되지만, configure 함수 호출 시 기존에 transports가 있다면 클리어합니다. 그리고 configure 함수의 인자로 전달받은 transports 리스트를 순회해서 각각에 대해 logger의 add 메서드를 호출합니다. 즉, createLogger는 logger 인스턴스를 반환하는데, 생성자 호출에서 내부적으로 add 메서드를 호출하는 셈입니다. 이제 add 메서드 구성만 보면 원인을 찾을 수 있을 것 같습니다.

  add(transport) {
    // Support backwards compatibility with all existing `winston < 3.x.x`
    // transports which meet one of two criteria:
    // 1. They inherit from winston.Transport in  < 3.x.x which is NOT a stream.
    // 2. They expose a log method which has a length greater than 2 (i.e. more then
    //    just `log(info, callback)`.
    const target =
      !isStream(transport) || transport.log.length > 2
        ? new LegacyTransportStream({ transport })
        : transport;

    if (!target._writableState || !target._writableState.objectMode) {
      throw new Error(
        'Transports must WritableStreams in objectMode. Set { objectMode: true }.'
      );
    }

    // Listen for the `error` event and the `warn` event on the new Transport.
    this._onEvent('error', target);
    this._onEvent('warn', target);
    this.pipe(target);

    if (transport.handleExceptions) {
      this.exceptions.handle();
    }

    if (transport.handleRejections) {
      this.rejections.handle();
    }

    return this;
  }

생각보다 별 내용이 없습니다. 검증부를 통과하면 이벤트를 등록하고 Logger의 pipe 메서드를 호출합니다. pipe 메서드가 이번 오류와 관련이 있는 것 같습니다. pipe 메서드는 Logger가 상속하는 Transform 클래스에 정의되어 있고, Transform 클래스는 'readable-stream' 라이브러리에 정의되어 있습니다. readable-stream 코드를 보면 Transform 클래스는 Duplex를 상속하고, Duplex 클래스는 다시 Readable 클래스를 상속합니다. 그리고 Readable 클래스에서 pipe 메서드를 정의합니다.

// readable-stream/lib/internal/streams/readable.js - pipe
Readable.prototype.pipe = function (dest, pipeOpts) {
  const src = this
  const state = this._readableState
  if (state.pipes.length === 1) {
    if (!state.multiAwaitDrain) {
      state.multiAwaitDrain = true
      state.awaitDrainWriters = new SafeSet(state.awaitDrainWriters ? [state.awaitDrainWriters] : [])
    }
  }
  // dest를 readableState.pipes 필드에 추가한다.
  state.pipes.push(dest)
  debug('pipe count=%d opts=%j', state.pipes.length, pipeOpts)
  const doEnd = (!pipeOpts || pipeOpts.end !== false) && dest !== process.stdout && dest !== process.stderr
  const endFn = doEnd ? onend : unpipe
  if (state.endEmitted) process.nextTick(endFn)
  else src.once('end', endFn)
  dest.on('unpipe', onunpipe)
  function onunpipe(readable, unpipeInfo) { /* ... */}
  function onend() {
    debug('onend')
    dest.end()
  }
  let ondrain
  let cleanedUp = false
  function cleanup() { /* ... */}
  function pause() { /* ... */}
  src.on('data', ondata)
  function ondata(chunk) { /* ... */ }

  // If the dest has an error, then stop piping into it.
  // However, don't suppress the throwing behavior for this.
  function onerror(er) { /* ... */ }

  // Make sure our error handler is attached before userland ones.
  prependListener(dest, 'error', onerror)

  // Both close and finish should trigger unpipe, but only once.
  function onclose() {
    dest.removeListener('finish', onfinish)
    unpipe()
  }
  dest.once('close', onclose)
  function onfinish() { /* ... */ }
  dest.once('finish', onfinish)
  function unpipe() {
    debug('unpipe')
    src.unpipe(dest)
  }

  // Tell the dest that it's being piped to.
  dest.emit('pipe', src)

  // Start the flow if it hasn't been started already.

  if (dest.writableNeedDrain === true) {
    pause()
  } else if (!state.flowing) {
    debug('pipe resume')
    src.resume()
  }
  return dest
}

dest, 즉 우리가 넘겨주는 transport 인스턴스를 스트림으로 연결하는 로직인 것 같습니다. 자세한 부분은 더 분석해봐야겠지만, 일단 12라인의 state.pipes.push(dest)가 여기서 호출됩니다. 그래도 logger.transports를 출력하면 추가된 transport 자체는 나와야할 것 같습니다. 이 문제는 다시 Logger 클래스 정의로 돌아가서 아래 코드를 보면 해소가 됩니다.

// Logger 클래스
Object.defineProperty(Logger.prototype, 'transports', {
  configurable: false,
  enumerable: true,
  get() {
    const { pipes } = this._readableState;
    return !Array.isArray(pipes) ? [pipes].filter(Boolean) : pipes;
  }
});

Logger 클래스의 transports 프로퍼티를 다시 정의하는 부분입니다. getter를 보시면 _readableState의 pipes 변수를 불러오는데, 이것이 Readable 클래스에서 호출한 pipe 메서드의 결과들입니다. 다시 말해, Readable 클래스의 pipe 메서드에서 _readableState의 pipes에 dest 객체를 넣는데, 여기서 [pipes].filter(Boolean), 즉 undefined나 null인 요소를 필터링하므로 접근해도 아무것도 없었던 것입니다.

References

• winston github
• readable-stream github