[토이프로젝트] 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);
        // 이후 작업..
}

'프로젝트 > MailBadara' 카테고리의 다른 글

[토이프로젝트] MailBadara - (7) 1차 서버 리팩토링 (1)	2023.11.22
[토이프로젝트] MailBadara - (6) 서버 최적화 생각 중 (0)	2023.10.16
[토이프로젝트] MailBadara - (4) 프론트 최적화 (0)	2023.10.13
[토이프로젝트] MailBadara - (3) 베타테스트 및 피드백 (1)	2023.10.08
[토이프로젝트] MailBadara - (2) MVP 개발 (1)	2023.10.08

axios timeout

Client network socket disconnected before secure TLS connection was established.

failed with exit code 137.

전역변수 tranporter 제거

전역변수 waitingQueue 제거

비동기 작업 분리

'프로젝트 > MailBadara' 카테고리의 다른 글

티스토리툴바