slackapi / bolt-js

A framework to build Slack apps using JavaScript
https://slack.dev/bolt-js
MIT License
2.73k stars 392 forks source link

Keep getting ETIMEDOUT errors / warning messages #2185

Closed SEEWON closed 1 day ago

SEEWON commented 1 month ago

Hi there, I'm getting warnings / errors from bolt.js.

@slack/bolt version

^3.19.0

Your App and Receiver Configuration

const receiver = new ExpressReceiver({
  signingSecret: process.env.SLACK_SIGNING_SECRET,
  port: process.env.SLACK_APP_PORT,
  clientId: process.env.SLACK_CLIENT_ID,
  clientSecret: process.env.SLACK_CLIENT_SECRET,
  stateSecret: "my-state-secret",
  scopes: [
    "channels:history",
    "chat:write",
    "chat:write.public",
    "commands",
    "emoji:read",
    "files:read",
    "files:write",
    "groups:history",
    "im:history",
    "im:write",
    "mpim:history",
    "users:read",
    "users:read.email",
  ],
...

Node.js runtime version

v18.17.1

Steps to reproduce:

Just by sending HTTP POST request to Slack API Webhook URL, with axios (like "https://hooks.slack.com/services/TXXXXXXXXXX/BXXXXXXXXXX/abcd1234": details masked)

Expected result:

No warnings, nor errors while sending HTTP POST request, message sent to slack.

Actual result:

Getting warnings, then ETIMEDOUT errors. (No message sent that should be sent) Errors are all from 35.73.126.78:443 / 35.74.58.174:443 / 52.192.46.121:443 / 52.196.128.139:443 IPs. Just figured out those IPs are from AWS, Tokyo region (seem to be slack's, same with result of nslookup https://hooks.slack.com)

Logs below are example for the warning, errors i've got from my server. 2024-08-05 19:07:13: [WARN] bolt-app http request failed connect ETIMEDOUT 52.192.46.121:443 2024-08-05 18:49:53: [WARN] bolt-app http request failed connect ETIMEDOUT 35.74.58.174:443 AxiosError: connect ETIMEDOUT 35.74.58.174:443 ...

This warnings/errors are keep coming out since July 25th. (fyi. There was no problem before July 25th, same code with was running since January, but the error started coming out since July 25th) Is something broken with bolt.js or Slack API?

Requirements

For general questions/issues about Slack API platform or its server-side, could you submit questions at https://my.slack.com/help/requests/new instead. :bow:

Please read the Contributing guidelines and Code of Conduct before creating this issue or pull request. By submitting, you are agreeing to those rules.

hello-ashleyintech commented 1 month ago

Hi, @SEEWON! Thanks for submitting this 😄

To confirm - you're getting the ETIMEDOUT error when your Bolt app attempts to send a message to Slack, is that right? If so, could you send me a snippet of how you're attempting to send the message to Slack from your app?

SEEWON commented 1 month ago

Hi @hello-ashleyintech 😊 Thanks for your help.

Correct. My code is just normally using axios to call HTTP POST method as below:

const axios = require('axios');

  const outboundPostData = {
    text: `${message}`,
    blocks: [
      {
        type: 'section',
        text: {
          type: 'mrkdwn',
          text: `${ID}`,
        },
      },
      {
        type: 'section',
        text: {
          type: 'mrkdwn',
          text: `${message}`,
        },
      },
    ],
  };

  try {
    await axios.post(process.env.USAGE_CC_WEBHOOK_URL, outboundPostData, {
      headers: {
        'Content-Type': 'application/json',
      },
    });
  } catch (error) {
    console.error('usageCC #38\n', error);
    errorCC('usageCC', 'usageCC #38', error.message);
  }

In fact, same code as above had no problem during times from last year, so i'm guessing the problem is something without the code.

Strange thing is that request is not always failing, it fails like once when i make 10 to 20 request in 10 minutes. While writing this i've just got same error again (20 mins ago) as below, so attaching the full error log: (with details about specific webhook URL/Block kit msgs masked)

 2024-08-06 09:49:55: usageCC #38
 AxiosError: connect ETIMEDOUT 35.74.58.174:443
    at AxiosError.from (/var/lib/jenkins/workspace/Webserver-CICD-Pipeline/node_modules/axios/dist/node/axios.cjs:837:14)
    at RedirectableRequest.handleRequestError (/var/lib/jenkins/workspace/Webserver-CICD-Pipeline/node_modules/axios/dist/node/axios.cjs:3090:25)
    at RedirectableRequest.emit (node:events:514:28)
    at eventHandlers.<computed> (/var/lib/jenkins/workspace/Webserver-CICD-Pipeline/node_modules/follow-redirects/index.js:38: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) {
  port: 443,
  address: '35.74.58.174',
  syscall: 'connect',
  code: 'ETIMEDOUT',
  errno: -110,
  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: 'application/json, text/plain, */*',
      'Content-Type': 'application/json',
      'User-Agent': 'axios/1.6.5',
      'Content-Length': '251',
      'Accept-Encoding': 'gzip, compress, deflate, br'
    },
    method: 'post',
    url: 'https://hooks.slack.com/services/T000000/B000000/abcd1234',
    data: '{"text":"ABC1234","blocks":[{"type":"section","text":{"type":"mrkdwn","text":"ABC1234"}},{"type":"section","text":{"type":"mrkdwn","text":"DEF1234"}}]}'
  },
  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: '/services/T000000/B000000/abcd1234',
      method: 'POST',
      headers: [Object: null prototype],
      agents: [Object],
      auth: undefined,
      family: undefined,
      beforeRedirect: [Function: dispatchBeforeRedirect],
      beforeRedirects: [Object],
      hostname: 'hooks.slack.com',
      port: '',
      agent: undefined,
      nativeProtocols: [Object],
      pathname: '/services/T000000/B000000/abcd1234'
    },
    _ended: false,
    _ending: true,
    _redirectCount: 0,
    _redirects: [],
    _requestBodyLength: 251,
    _requestBodyBuffers: [ [Object] ],
    _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: true,
      sendDate: false,
      _removedConnection: false,
      _removedContLen: false,
      _removedTE: false,
      strictContentLength: false,
      _contentLength: '251',
      _hasBody: true,
      _trailer: '',
      finished: false,
      _headerSent: true,
      _closed: false,
      socket: [TLSSocket],
      _header: 'POST /services/T000000/B000000/abcd1234 HTTP/1.1\r\n' +
        'Accept: application/json, text/plain, */*\r\n' +
        'Content-Type: application/json\r\n' +
        'User-Agent: axios/1.6.5\r\n' +
        'Content-Length: 251\r\n' +
        'Accept-Encoding: gzip, compress, deflate, br\r\n' +
        'Host: hooks.slack.com\r\n' +
        'Connection: close\r\n' +
        '\r\n',
      _keepAliveTimeout: 0,
      _onPendingData: [Function: nop],
      agent: [Agent],
      socketPath: undefined,
      method: 'POST',
      maxHeaderSize: undefined,
      insecureHTTPParser: undefined,
      joinDuplicateHeaders: undefined,
      path: '/services/T000000/B000000/abcd1234',
      _ended: false,
      res: null,
      aborted: false,
      timeoutCb: null,
      upgradeOrConnect: false,
      parser: null,
      maxHeadersCount: null,
      reusedSocket: false,
      host: 'hooks.slack.com',
      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://hooks.slack.com/services/T000000/B000000/abcd1234',
    [Symbol(kCapture)]: false
  },
  cause: Error: connect ETIMEDOUT 35.74.58.174:443
      at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1495:16) {
    errno: -110,
    code: 'ETIMEDOUT',
    syscall: 'connect',
    address: '35.74.58.174',
    port: 443
  }
}
hello-ashleyintech commented 1 month ago

Hi, @SEEWON! 😄 thanks for sending that additional info over.

Based on the code provided, as well as it seeming that the timeout errors are intermittent and usually occur after a large amount of requests are placed in a short span, I would suggest trying to add a timeout property and httpsAgent property to your Axios instance when you initialize it to account for longer requests. Within httpsAgent, you can set keepAlive to true. More info can be found in the Axios docs here.

Hopefully that should help with the timeout failures! Let me know if you continue to run into issues! 🙌

dianexjeong commented 1 month ago

Hello @hello-ashleyintech, Diane here from @SEEWON's team. Thanks for letting us know about the httpsAgent property.

I have modified the usageCC code as follows(the usageCC is the file that ran into ETIMEDOUT issues):

const https = require("https");
const { errorCC } = require("./errorCC.js");
const axios = require("axios");

const httpsAgent = new https.Agent({ keepAlive: true });

module.exports.usageCC = async (teamId, message) => {
  require("./config.js");

  const outboundPostData = {
    text: `${message}`,
    blocks: [
      {
        type: "section",
        text: {
          type: "mrkdwn",
          text: `${teamId} 😆`,
        },
      },
      {
        type: "section",
        text: {
          type: "mrkdwn",
          text: `${message}`,
        },
      },
    ],
  };

  try {
    await axios.post(process.env.USAGE_CC_WEBHOOK_URL, outboundPostData, {
      headers: {
        "Content-Type": "application/json",
      },
      httpsAgent: httpsAgent, 
      timeout: 60000,
    });
    // console.log(result);
  } catch (error) {
    console.error("usageCC #38\n", error);
    errorCC("batch", "usageCC #38", error.message);
  }
};

as you can see, I have added the timeout and httpsAgent properties.

After this modification, the ETIMEDOUT error doesn't occur anymore - but a new problem arose.

Right now, I am reusing the https.Agent instead of creating a new https.Agent per every request. I have tried both methods - using a single instance and reusing it across multiple requests and creating a new https.Agent for every request -but I am still running into the following error: AxiosError: timeout of 60000ms exceeded with the code ECONNABORTED.

Here is the full error log:

2024-08-14 22:19:51: 
AxiosError: timeout of 60000ms exceeded
    at RedirectableRequest.handleRequestTimeout (/var/lib/jenkins/workspace/Dev-Babywhale-CICD-Pipeline/node_modules/axios/dist/node/axios.cjs:3053:16)
    at RedirectableRequest.emit (node:events:514:28)
    at Timeout.<anonymous> (/var/lib/jenkins/workspace/Dev-Babywhale-CICD-Pipeline/node_modules/follow-redirects/index.js:169:12)
    at listOnTimeout (node:internal/timers:569:17)
    at process.processTimers (node:internal/timers:512:7) {
  code: 'ECONNABORTED',
  config: {
    transitional: {
      silentJSONParsing: true,
      forcedJSONParsing: true,
      clarifyTimeoutError: false
    },
    adapter: 'http',
    transformRequest: [ [Function: transformRequest] ],
    transformResponse: [ [Function: transformResponse] ],
    timeout: 60000,
    xsrfCookieName: 'XSRF-TOKEN',
    xsrfHeaderName: 'X-XSRF-TOKEN',
    maxContentLength: -1,
    maxBodyLength: -1,
    env: { FormData: [Function], Blob: [class Blob] },
    validateStatus: [Function: validateStatus],
    headers: Object [AxiosHeaders] {
      Accept: 'application/json, text/plain, */*',
      'Content-Type': 'application/json',
      'User-Agent': 'axios/1.5.0',
      'Content-Length': '189',
      'Accept-Encoding': 'gzip, compress, deflate, br'
    },
    httpsAgent: Agent {
      _events: [Object: null prototype],
      _eventsCount: 2,
      _maxListeners: undefined,
      defaultPort: 443,
      protocol: 'https:',
      options: [Object: null prototype],
      requests: [Object: null prototype] {},
      sockets: [Object: null prototype],
      freeSockets: [Object: null prototype] {},
      keepAliveMsecs: 1000,
      keepAlive: true,
      maxSockets: Infinity,
      maxFreeSockets: 256,
      scheduling: 'lifo',
      maxTotalSockets: Infinity,
      totalSocketCount: 1,
      maxCachedSessions: 100,
      _sessionCache: [Object],
      [Symbol(kCapture)]: false
    },
    method: 'post',
    url: 'https://hooks.slack.com/services/T0000R/B0000/000',
    data: '{"text":"abc","blocks":[{"type":"section","text":{"type":"mrkdwn","text":"abc"}},{"type":"section","text":{"type":"mrkdwn","text":"abc"}}]}'
  },
  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: '/services/T00000/B00000/000000',
      method: 'POST',
      headers: [Object: null prototype],
      agents: [Object],
      auth: undefined,
      family: undefined,
      beforeRedirect: [Function: dispatchBeforeRedirect],
      beforeRedirects: [Object],
      hostname: 'hooks.slack.com',
      port: '',
      agent: [Agent],
      nativeProtocols: [Object],
      pathname: '/services/T00000/B00000/000000'
    },
    _ended: false,
    _ending: true,
    _redirectCount: 0,
    _redirects: [],
    _requestBodyLength: 189,
    _requestBodyBuffers: [ [Object] ],
    _onNativeResponse: [Function (anonymous)],
    _currentRequest: ClientRequest {
      _events: [Object: null prototype],
      _eventsCount: 7,
      _maxListeners: undefined,
      outputData: [],
      outputSize: 0,
      writable: true,
      destroyed: false,
      _last: false,
      chunkedEncoding: false,
      shouldKeepAlive: true,
      maxRequestsOnConnectionReached: false,
      _defaultKeepAlive: true,
      useChunkedEncodingByDefault: true,
      sendDate: false,
      _removedConnection: false,
      _removedContLen: false,
      _removedTE: false,
      strictContentLength: false,
      _contentLength: '189',
      _hasBody: true,
      _trailer: '',
      finished: false,
      _headerSent: true,
      _closed: false,
      socket: [TLSSocket],
      _header: 'POST /services/T00000/B00000/00000 HTTP/1.1\r\n' +
        'Accept: application/json, text/plain, */*\r\n' +
        'Content-Type: application/json\r\n' +
        'User-Agent: axios/1.5.0\r\n' +
        'Content-Length: 189\r\n' +
        'Accept-Encoding: gzip, compress, deflate, br\r\n' +
        'Host: hooks.slack.com\r\n' +
        'Connection: keep-alive\r\n' +
        '\r\n',
      _keepAliveTimeout: 0,
      _onPendingData: [Function: nop],
      agent: [Agent],
      socketPath: undefined,
      method: 'POST',
      maxHeaderSize: undefined,
      insecureHTTPParser: undefined,
      joinDuplicateHeaders: undefined,
      path: '/services/T00000/B00000/000000',
      _ended: false,
      res: null,
      aborted: false,
      timeoutCb: null,
      upgradeOrConnect: false,
      parser: [HTTPParser],
      maxHeadersCount: null,
      reusedSocket: false,
      host: 'hooks.slack.com',
      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://hooks.slack.com/services/T00000/B00000/000000',
    _timeout: null,
    [Symbol(kCapture)]: false
  }
}

Is this simply an issue of too many requests being thrown?

Two things that are also bothering me is that a) I am not sending a huge bulk of http POST requests at the same time - I usually am calling the usageCC function once per minute or so, and the issue still happens then. b) I started to get some expired_trigger_id errors upon modal interactions along the same time period with the ETIMEDOUT errors - although not so frequent, it has never came across my app until the very recently, similar to when the ETIMEDOUT errors started happening(July 25th). I'm suspecting that this could be related to the cause of the ETIMEDOUT errors.

What could be the issue here?

dianexjeong commented 4 weeks ago

Hello @hello-ashleyintech,

to follow up - I got this error message this morning.

Screenshot 2024-08-16 at 2 57 00 PM

along with the ECONNABORTED I mentioned yesterday, I started getting ECONNRESET errors as well - and as you can see in the image above, it seems that the ETIMEDOUT errors are persisting even after the addition of the httpsAgent and timeout configurations. 😢

zimeg commented 4 weeks ago

👋 Marked this as server-side-issue for now since I believe this is caused from slow responses to requests and not settings in the app.

I shared a few troubleshooting suggestions in #2212 but the one I am most curious about is updating the Bolt version to ^3.21.1 for the fetch adapter from axios.

dianexjeong commented 3 weeks ago

update: I tried using the native fetch method instead of axios for my usageCC, but I'm still getting timeout errors. image

Here's my refactored usageCC:

const https = require("https");
const { errorCC } = require("./errorCC.js");

const httpsAgent = new https.Agent({ keepAlive: true });

const fetchWithTimeout = (url, options, timeout = 5000) => {
  return Promise.race([
    fetch(url, options),
    new Promise((_, reject) => setTimeout(() => reject(new Error("Request timed out")), timeout)),
  ]);
};

module.exports.usageCC = async (teamId, message) => {
  require("./config.js");

  const outboundPostData = {
    text: `${message}`,
    blocks: [
      {
        type: "section",
        text: {
          type: "mrkdwn",
          text: `${teamId} 😆`,
        },
      },
      {
        type: "section",
        text: {
          type: "mrkdwn",
          text: `${message}`,
        },
      },
    ],
  };

  try {
    const response = await fetchWithTimeout(
      process.env.USAGE_CC_WEBHOOK_URL,
      {
        method: "POST",
        headers: {
          "Content-Type": "application/json",
        },
        body: JSON.stringify(outboundPostData),
        agent: httpsAgent, 
      },
      60000
    );

    if (!response.ok) {
      throw new Error(`HTTP error! status: ${response.status}`);
    }
  } catch (error) {
    console.error("usageCC #38\n", error);
    errorCC("batch", "usageCC #38", error.message);
  }
};
filmaj commented 2 days ago

Hello, checking in here. Is this still a problem for you @SEEWON @dianexjeong ?

Another idea here: are you using a proxy?

dianexjeong commented 1 day ago

I believe we can combine / merge this issue with #2212 :)

filmaj commented 1 day ago

Yes that makes sense to me as well. Closing and let's continue in #2212.