Request failed to complete in x ms (randomly) and it looks like event loop get blocked

[SteadEXE]

Sometime, randomly queries start to fail, while it continues to work using the same user and same query on SQL Server Management Studio. I don't know yet if this is caused by the node-mssql/tedious or an issue with SQL server itself. It was looking like this issue: https://github.com/tediousjs/node-mssql/issues/1407 What is weird, is that when a request timeout. CPU usage rises up to 100% on one core. And the whole node process stop to react to CTRL+C or incoming HTTP requests. Aslong the requests work back, CPU usage fall to a normal CPU usage.

Feel free to ask me any details. We are really struggling troubleshooting the cause of the issue. As mentioned, for the queries failing we are still not sure why it randomly fails.

Expected behaviour:

I expect my requests to not fail (if it's a bug within tedious ofcourse). I also expect the event loop to not be blocked.

Actual behaviour:

This is one of the failing query which continues to work in SQL Studio :

const request = this.connectionPool.request();
const response = await request.query(` SELECT DISTINCT LocationName FROM Locations`);

Here is the logs:

[Nest] 4156  - 05/04/2023 11:06:03   ERROR [ExceptionsHandler] Timeout: Request failed to complete in 60000ms
RequestError: Timeout: Request failed to complete in 60000ms
    at D:\Applications\factory-toolbox\apps\backend\node_modules\.pnpm\mssql@9.1.1\node_modules\mssql\lib\tedious\request.js:449:19
    at Array.forEach (<anonymous>)
    at Request.userCallback (D:\Applications\factory-toolbox\apps\backend\node_modules\.pnpm\mssql@9.1.1\node_modules\mssql\lib\tedious\request.js:446:46)
    at Request.callback (D:\Applications\factory-toolbox\apps\backend\node_modules\.pnpm\tedious@15.1.3\node_modules\tedious\lib\request.js:205:14)
    at D:\Applications\factory-toolbox\apps\backend\node_modules\.pnpm\tedious@15.1.3\node_modules\tedious\lib\connection.js:2866:24
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
[Nest] 4156  - 05/04/2023 11:06:03   ERROR [ExceptionsHandler] Timeout: Request failed to complete in 60000ms
RequestError: Timeout: Request failed to complete in 60000ms
    at D:\Applications\factory-toolbox\apps\backend\node_modules\.pnpm\mssql@9.1.1\node_modules\mssql\lib\tedious\request.js:449:19
    at Array.forEach (<anonymous>)
    at Request.userCallback (D:\Applications\factory-toolbox\apps\backend\node_modules\.pnpm\mssql@9.1.1\node_modules\mssql\lib\tedious\request.js:446:46)
    at Request.callback (D:\Applications\factory-toolbox\apps\backend\node_modules\.pnpm\tedious@15.1.3\node_modules\tedious\lib\request.js:205:14)
    at D:\Applications\factory-toolbox\apps\backend\node_modules\.pnpm\tedious@15.1.3\node_modules\tedious\lib\connection.js:2866:24
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
[Nest] 4156  - 05/04/2023 11:06:03   ERROR [ExceptionsHandler] Timeout: Request failed to complete in 60000ms
RequestError: Timeout: Request failed to complete in 60000ms
    at D:\Applications\factory-toolbox\apps\backend\node_modules\.pnpm\mssql@9.1.1\node_modules\mssql\lib\tedious\request.js:449:19
    at Array.forEach (<anonymous>)
    at Request.userCallback (D:\Applications\factory-toolbox\apps\backend\node_modules\.pnpm\mssql@9.1.1\node_modules\mssql\lib\tedious\request.js:446:46)
    at Request.callback (D:\Applications\factory-toolbox\apps\backend\node_modules\.pnpm\tedious@15.1.3\node_modules\tedious\lib\request.js:205:14)
    at D:\Applications\factory-toolbox\apps\backend\node_modules\.pnpm\tedious@15.1.3\node_modules\tedious\lib\connection.js:2866:24
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)

Configuration:

let connection = new ConnectionPool({
      user: configService.get<string>('mssql.username'),
      password: configService.get<string>('mssql.password'),
      server: configService.get<string>('mssql.server'),
      database: configService.get<string>('mssql.database'),
      requestTimeout: 60e3,
      options: {
        encrypt: false
      },
      pool: {
        max: 10,
        min: 1
      }
});

await connection.connect();

Software versions

• NodeJS: v18.14.1
• node-mssql: v9.1.1
• SQL Server: SQL Server 2014 (12.0.4100)

[dhensby]

If you turn the debug logs on (set the DEBUG env var) what output do you get? Do you see the logs stop when the event loop is blocked?

Do you have other code that makes up your application that could be contributing to the event loop blocking issue?

[SteadEXE]

Sorry for the delay, I didn't had the issue for a while, next time it happens, I will try 👍

[dhensby]

OK - if you're not experiencing it at the moment, I'll close this and will re-open if you're able to give an update.