[토이프로젝트] MailBadara - (5) 트러블슈팅

트러블슈팅

axios timeout

• 상황: 특정 시간이 되면 서버에서 크롤링 작업을 수행 후, DB의 유저들에게 메일을 뿌려야 한다. 그러나 서버에서 크롤링 작업을 수행할 때 크롤링 대상 사이트의 속도가 너무 느려서 axios.get의 반환이 늦어짐에 따라 timeout: 3초로 제한을 두었다. 그런데 어떤 때는 크롤링을 빠르게 잘하는 반면, 어떤 때는 너무 느려서 timeout: 3초가 계속해서 터진다.
• 솔루션: 크롤링 대상인 학과 홈페이지들의 서버 상태가 시시각각 달라져서 timeout을 지정하기가 애매했다.
• 작업이 길어질수록 메모리 사용량이 커질 것 같았지만, timeout을 무제한으로 두는 수밖에 없었다.

 

• 서버 로그

AxiosError: timeout of 3000ms exceeded at RedirectableRequest.handleRequestTimeout (file:///workspace/server/node_modules/axios/lib/adapters/http.js:630:16) at RedirectableRequest.emit (node:events:514:28) at Timeout.<anonymous> (/workspace/server/node_modules/follow-redirects/index.js:179:12) at listOnTimeout (node:internal/timers:573:17) at process.processTimers (node:internal/timers:514:7) { code: 'ECONNABORTED', config: { transitional: { silentJSONParsing: true, forcedJSONParsing: true, clarifyTimeoutError: false }, adapter: [ 'xhr', 'http' ], transformRequest: [ [Function: transformRequest] ], transformResponse: [ [Function: transformResponse] ], timeout: 3000, xsrfCookieName: 'XSRF-TOKEN', xsrfHeaderName: 'X-XSRF-TOKEN', maxContentLength: -1, maxBodyLength: -1, env: { FormData: [Function], Blob: [class Blob] }, validateStatus: [Function: validateStatus], headers: Object [AxiosHeaders] { Accept: 'text/xml', 'Content-Type': 'application/rss+xml', 'User-Agent': 'axios/1.5.1', 'Accept-Encoding': 'gzip, compress, deflate, br' }, method: 'get', url: 'https://biz.pusan.ac.kr/bbs/biz/2556/rssList.do?row=5', data: undefined }, request: <ref *1> Writable { _writableState: WritableState { objectMode: false, highWaterMark: 16384, finalCalled: false, needDrain: false, ending: false, ended: false, finished: false, destroyed: false, decodeStrings: true, defaultEncoding: 'utf8', length: 0, writing: false, corked: 0, sync: true, bufferProcessing: false, onwrite: [Function: bound onwrite], writecb: null, writelen: 0, afterWriteTickInfo: null, buffered: [], bufferedIndex: 0, allBuffers: true, allNoop: true, pendingcb: 0, constructed: true, prefinished: false, errorEmitted: false, emitClose: true, autoDestroy: true, errored: null, closed: false, closeEmitted: false, [Symbol(kOnFinished)]: [] }, _events: [Object: null prototype] { response: [Function: handleResponse], error: [Function: handleRequestError], socket: [Array] }, _eventsCount: 3, _maxListeners: undefined, _options: { maxRedirects: 21, maxBodyLength: Infinity, protocol: 'https:', path: '/bbs/biz/2556/rssList.do?row=5', method: 'GET', headers: [Object: null prototype], agents: [Object], auth: undefined, family: undefined, beforeRedirect: [Function: dispatchBeforeRedirect], beforeRedirects: [Object], hostname: 'biz.pusan.ac.kr', port: '', agent: undefined, nativeProtocols: [Object], pathname: '/bbs/biz/2556/rssList.do', search: '?row=5' }, _ended: true, _ending: true, _redirectCount: 0, _redirects: [], _requestBodyLength: 0, _requestBodyBuffers: [], _onNativeResponse: [Function (anonymous)], _currentRequest: ClientRequest { _events: [Object: null prototype], _eventsCount: 7, _maxListeners: undefined, outputData: [], outputSize: 0, writable: true, destroyed: false, _last: true, chunkedEncoding: false, shouldKeepAlive: true, maxRequestsOnConnectionReached: false, _defaultKeepAlive: true, useChunkedEncodingByDefault: false, sendDate: false, _removedConnection: false, _removedContLen: false, _removedTE: false, strictContentLength: false, _contentLength: 0, _hasBody: true, _trailer: '', finished: true, _headerSent: true, _closed: false, socket: [TLSSocket], _header: 'GET /bbs/biz/2556/rssList.do?row=5 HTTP/1.1\r\n' + 'Accept: text/xml\r\n' + 'Content-Type: application/rss+xml\r\n' + 'User-Agent: axios/1.5.1\r\n' + 'Accept-Encoding: gzip, compress, deflate, br\r\n' + 'Host: biz.pusan.ac.kr\r\n' + 'Connection: keep-alive\r\n' + '\r\n', _keepAliveTimeout: 0, _onPendingData: [Function: nop], agent: [Agent], socketPath: undefined, method: 'GET', maxHeaderSize: undefined, insecureHTTPParser: undefined, joinDuplicateHeaders: undefined, path: '/bbs/biz/2556/rssList.do?row=5', _ended: false, res: null, aborted: false, timeoutCb: [Function: emitRequestTimeout], upgradeOrConnect: false, parser: [HTTPParser], maxHeadersCount: null, reusedSocket: false, host: 'biz.pusan.ac.kr', protocol: 'https:', _redirectable: [Circular *1], [Symbol(kCapture)]: false, [Symbol(kBytesWritten)]: 0, [Symbol(kNeedDrain)]: false, [Symbol(corked)]: 0, [Symbol(kOutHeaders)]: [Object: null prototype], [Symbol(errored)]: null, [Symbol(kHighWaterMark)]: 16384, [Symbol(kRejectNonStandardBodyWrites)]: false, [Symbol(kUniqueHeaders)]: null }, _currentUrl: 'https://biz.pusan.ac.kr/bbs/biz/2556/rssList.do?row=5', _timeout: null, [Symbol(kCapture)]: false } } Killed error Command failed with exit code 137. error Command failed with exit code 137. info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command. info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command. Instance is unhealthy yarn run v1.22.19 Instance is healthy $ cd server && yarn start $ node app.js

 

Client network socket disconnected before secure TLS connection was established.

• 상황: 특정 학과 홈페이지를 크롤링할 때는 80%의 확률로 해당 에러가 발생한다. 다른 학과 홈페이지를 크롤링할 때는 문제가 없었기 때문에 특정 학과의 서버 문제임을 알 수 있다.
• 솔루션: 학과 서버 문제는 내가 할 수 있는게 없기 때문에 해당 학과는 DB에서 제거하는 수 밖에 없었다. 20%의 확률로 크롤해오기는 해서, 성공할 때까지 schedulingJobs를 재실행할 수도 있었지만 괜히 리소스를 낭비할거라 생각해 시도하지는 않았다.

AxiosError: Client network socket disconnected before secure TLS connection was established
  at AxiosError.from (file:///usr/src/app/server/node_modules/axios/lib/core/AxiosError.js:89:14)
  at RedirectableRequest.handleRequestError (file:///usr/src/app/server/node_modules/axios/lib/adapters/http.js:593:25)
  at RedirectableRequest.emit (node:events:514:28)
  at eventHandlers.<computed> (/usr/src/app/server/node_modules/follow-redirects/index.js:14:24)
  at ClientRequest.emit (node:events:514:28)
  at TLSSocket.socketErrorListener (node:_http_client:501:9)
  at TLSSocket.emit (node:events:514:28)
  at emitErrorNT (node:internal/streams/destroy:151:8)
  at emitErrorCloseNT (node:internal/streams/destroy:116:3)
  at process.processTicksAndRejections (node:internal/process/task_queues:82:21) {
localAddress: undefined,
port: 443,
host: 'cse.snu.ac.kr',
path: null,
code: 'ECONNRESET',
config: {
  transitional: {
    silentJSONParsing: true,
    forcedJSONParsing: true,
    clarifyTimeoutError: false
  },
  adapter: [ 'xhr', 'http' ],
  transformRequest: [ [Function: transformRequest] ],
  transformResponse: [ [Function: transformResponse] ],
  timeout: 0,
  xsrfCookieName: 'XSRF-TOKEN',
  xsrfHeaderName: 'X-XSRF-TOKEN',
  maxContentLength: -1,
  maxBodyLength: -1,
  env: { FormData: [Function], Blob: [class Blob] },
  validateStatus: [Function: validateStatus],
  headers: Object [AxiosHeaders] {
    Accept: 'text/xml',
    'Content-Type': 'application/rss+xml',
    'User-Agent': 'axios/1.5.1',
    'Accept-Encoding': 'gzip, compress, deflate, br'
  },
  method: 'get',
  url: 'https://cse.snu.ac.kr/department-notices.xml?c%5B0%5D=40',
  data: undefined
},
request: <ref *1> Writable {
  _writableState: WritableState {
    objectMode: false,
    highWaterMark: 16384,
    finalCalled: false,
    needDrain: false,
    ending: false,
    ended: false,
    finished: false,
    destroyed: false,
    decodeStrings: true,
    defaultEncoding: 'utf8',
    length: 0,
    writing: false,
    corked: 0,
    sync: true,
    bufferProcessing: false,
    onwrite: [Function: bound onwrite],
    writecb: null,
    writelen: 0,
    afterWriteTickInfo: null,
    buffered: [],
    bufferedIndex: 0,
    allBuffers: true,
    allNoop: true,
    pendingcb: 0,
    constructed: true,
    prefinished: false,
    errorEmitted: false,
    emitClose: true,
    autoDestroy: true,
    errored: null,
    closed: false,
    closeEmitted: false,
    [Symbol(kOnFinished)]: []
  },
  _events: [Object: null prototype] {
    response: [Function: handleResponse],
    error: [Function: handleRequestError],
    socket: [Function: handleRequestSocket]
  },
  _eventsCount: 3,
  _maxListeners: undefined,
  _options: {
    maxRedirects: 21,
    maxBodyLength: Infinity,
    protocol: 'https:',
    path: '/department-notices.xml?c%5B0%5D=40',
    method: 'GET',
    headers: [Object: null prototype],
    agents: [Object],
    auth: undefined,
    family: undefined,
    beforeRedirect: [Function: dispatchBeforeRedirect],
    beforeRedirects: [Object],
    hostname: 'cse.snu.ac.kr',
    port: '',
    agent: undefined,
    nativeProtocols: [Object],
    pathname: '/department-notices.xml',
    search: '?c%5B0%5D=40'
  },
  _ended: true,
  _ending: true,
  _redirectCount: 0,
  _redirects: [],
  _requestBodyLength: 0,
  _requestBodyBuffers: [],
  _onNativeResponse: [Function (anonymous)],
  _currentRequest: ClientRequest {
    _events: [Object: null prototype],
    _eventsCount: 7,
    _maxListeners: undefined,
    outputData: [],
    outputSize: 0,
    writable: true,
    destroyed: false,
    _last: true,
    chunkedEncoding: false,
    shouldKeepAlive: false,
    maxRequestsOnConnectionReached: false,
    _defaultKeepAlive: true,
    useChunkedEncodingByDefault: false,
    sendDate: false,
    _removedConnection: false,
    _removedContLen: false,
    _removedTE: false,
    strictContentLength: false,
    _contentLength: 0,
    _hasBody: true,
    _trailer: '',
    finished: true,
    _headerSent: true,
    _closed: false,
    socket: [TLSSocket],
    _header: 'GET /department-notices.xml?c%5B0%5D=40 HTTP/1.1\r\n' +
      'Accept: text/xml\r\n' +
      'Content-Type: application/rss+xml\r\n' +
      'User-Agent: axios/1.5.1\r\n' +
      'Accept-Encoding: gzip, compress, deflate, br\r\n' +
      'Host: cse.snu.ac.kr\r\n' +
      'Connection: close\r\n' +
      '\r\n',
    _keepAliveTimeout: 0,
    _onPendingData: [Function: nop],
    agent: [Agent],
    socketPath: undefined,
    method: 'GET',
    maxHeaderSize: undefined,
    insecureHTTPParser: undefined,
    joinDuplicateHeaders: undefined,
    path: '/department-notices.xml?c%5B0%5D=40',
    _ended: false,
    res: null,
    aborted: false,
    timeoutCb: null,
    upgradeOrConnect: false,
    parser: null,
    maxHeadersCount: null,
    reusedSocket: false,
    host: 'cse.snu.ac.kr',
    protocol: 'https:',
    _redirectable: [Circular *1],
    [Symbol(kCapture)]: false,
    [Symbol(kBytesWritten)]: 0,
    [Symbol(kNeedDrain)]: false,
    [Symbol(corked)]: 0,
    [Symbol(kOutHeaders)]: [Object: null prototype],
    [Symbol(errored)]: null,
    [Symbol(kHighWaterMark)]: 16384,
    [Symbol(kRejectNonStandardBodyWrites)]: false,
    [Symbol(kUniqueHeaders)]: null
  },
  _currentUrl: 'https://cse.snu.ac.kr/department-notices.xml?c%5B0%5D=40',
  [Symbol(kCapture)]: false
},
cause: Error: Client network socket disconnected before secure TLS connection was established
    at connResetException (node:internal/errors:720:14)
    at TLSSocket.onConnectEnd (node:_tls_wrap:1605:19)
    at TLSSocket.emit (node:events:526:35)
    at endReadableNT (node:internal/streams/readable:1359:12)
    at process.processTicksAndRejections (node:internal/process/task_queues:82:21) {
  code: 'ECONNRESET',
  path: null,
  host: 'cse.snu.ac.kr',
  port: 443,
  localAddress: undefined
}
}
Killed
error Command failed with exit code 137.
error Command failed with exit code 137.
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.
yarn run v1.22.19
$ cd server && yarn server
$ node app.js

failed with exit code 137.

• 상황: cron 작업을 수행할 때마다 메모리 오버(137) 때문에 서버가 죽는 문제가 발생한다. koyeb의 무료 플랜을 사용 중이라 메모리(256mb)가 적긴 하다.
• 솔루션: 단순하게 유료 플랜으로 올려서 메모리를 업그레이드시키면 편하겠지만, 할 수 있는 데까지 서버 최적화를 해보기로 했다.

전역변수 tranporter 제거

// create email transporter.
global.transporter = nodemailer.createTransport({
  service: "gmail",
  host: "smtp.gmail.com",
  port: 587,
  secure: false,
  auth: {
    user: process.env.GOOGLE_MAIL_USER_ID,
    pass: process.env.GOOGLE_MAIL_APP_PASSWORD,
  },
});

nodemailer 라이브러리를 사용해서 메일을 전송하기 위해선 transporter를 생성해야 했고, 전역으로 한 번만 선언해서 사용 중이었다. 그러나 전역변수가 항상 메모리를 점유한다고 생각했고, 전역으로 선언하는 대신 schedulingJobs() 호출마다 생성해주는 방식으로 변경했다.

전역변수 waitingQueue 제거

global.waitingQueue = {};

// 구독 요청 시
global.waitingQueue[email] = {
      department_code: department,
      start_time: startTime,
    };

// check if email exist in waiting queue.
  if (
    !(email in global.waitingQueue) ||
    global.waitingQueue[email] === undefined
  ) {
    res.status(500).json({
      type: "ERROR",
      message: "Server error! Your email don't exist in waiting queue.",
    });
  }

// check if email validation is expired.
  if (isExpired(global.waitingQueue[email].start_time)) {
    delete global.waitingQueue[email];
    res.status(500).json({
      type: "ERROR",
      message: "Your email validation is expired.",
    });
  }

• 구독을 요청한 사람들을 검증하기 위해 이메일로 검증 메일을 전송함과 동시에 waitingQueue에 push한다. push된 시간부터 10분 이내에 검증 메일을 확인하지 못하면 expired 처리되며 waitingQueue에서 삭제한다.
• 마찬가지로 전역변수가 메모리를 점유한다 생각했고, 특히 object 타입이기 때문에 waitingQueue에 데이터가 쌓일수록 메모리를 잡아먹을 것 같았다.
• 솔루션: 전역변수를 제거하고, redis를 waitingQueue로 사용했다. waitingQueue에 대한 처리를 redis cloud에 맡김으로써 서버의 메모리 부담을 줄이고자 하였다.

// server/utils/Redis.js
import Redis from "ioredis";

export const initializeRedis = async () => {
  const port =
    process.env.NODE_ENV === "production"
      ? process.env.REDIS_LABS_PORT
      : process.env.REDIS_DOCKER_PORT;
  const host =
    process.env.NODE_ENV === "production"
      ? process.env.REDIS_LABS_HOST
      : process.env.REDIS_DOCKER_HOST;
  const options =
    process.env.NODE_ENV === "production"
      ? {
          password: process.env.REDIS_LABS_PASSWORD,
        }
      : {};
  const redisClient = new Redis(port, host, options);
  redisClient.on("connect", () => {
    console.log("[Success] Redis Connected");
  });
  redisClient.on("error", (err) => {
    console.log("[Error] Redis error: " + err);
  });
  return redisClient;
};

비동기 작업 분리

• 상황: 모든 학과의 여러 게시판에서 데이터를 긁어온 후, 모든 유저들에게 메일을 전송하는 작업을 수행해야 했기에 async/await 작업이 많이 들어갈 수 밖에 없었다. 여기서 비동기로 동시에 실행되는 작업이 많아서 메모리 부담이 가중된다 생각했고 리팩토링을 통해 비동기 코드를 전부 분리시켰다.
• 변경 전

// server/app.js
cron.schedule("0 2,9 * * 1-5", () => {
  const now = new Date();
  now.setHours(now.getHours() + 9);
  console.log(`[Cron] Fetching RSS data (${now}).`);
  Department.find({})
    .then(async (departments) => {
      if (departments.length === 0) {
        console.log("[Cron] Department is nothing.");
        // 이후 작업..
}

• 변경 후

// server/app.js
cron.schedule("0 2,9 * * 1-5", async () => {
  const now = new Date();
  now.setHours(now.getHours() + 9);
  console.log(`[Cron] Fetching RSS data (${now}).`);
  try {
    const departments = await Department.find({});
    if (departments.length === 0) {
      console.log("[Cron] Department is nothing.");
      return;
    }

    for (const department of departments) {
      if (department.boards.length === 0) {
        console.log("[Cron] No RSS data on", department.code);
        // 이후 작업..
}