RequestError: Failed to cancel request in 5000ms

[gsamal]

I got this error once while processing a million records. Technically I see there is a timer with cancel event, which triggered this. But unfortunately I don't have enough logs at this time to debug this and it's not reproducible.

request.once('cancel', () => {
        if (!this.isRequestActive(request)) {
          // Cancel was called on a request that is no longer active on this connection
          return;
        } // There's three ways to handle request cancelation:


        if (this.state === this.STATE.BUILDING_CLIENT_REQUEST) {
          // The request was cancelled before buffering finished
          this.request = undefined;
          request.callback((0, _errors.RequestError)('Canceled.', 'ECANCEL'));
          this.transitionTo(this.STATE.LOGGED_IN);
        } else if (message.writable) {
          // - if the message is still writable, we'll set the ignore bit
          //   and end the message.
          message.ignore = true;
          message.end();
        } else {
          // - but if the message has been ended (and thus has been fully sent off),
          //   we need to send an `ATTENTION` message to the server
          this.messageIo.sendMessage(_packet.TYPE.ATTENTION);
          this.transitionTo(this.STATE.SENT_ATTENTION);
        }

        this.clearRequestTimer();
        this.createCancelTimer(); // With timeout 5 sec
      });

I am not sure if it's relevant, should mention it anyway. The request was wrapped in a transaction. So, when the query failed with the above error, I wanted to rollback and I got another error while doing so.

TransactionError: Requests can only be made in the LoggedIn state, not the Final state
    at Request.userCallback (/node_modules/mssql/lib/tedious/transaction.js:83:24)
    at Request.callback (/node_modules/tedious/lib/request.js:56:14)
    at Connection.makeRequest (/node_modules/tedious/lib/connection.js:1800:15)
    at Connection.rollbackTransaction (/node_modules/tedious/lib/connection.js:1723:17)
    at Immediate.<anonymous> (/node_modules/mssql/lib/tedious/transaction.js:82:32)
    at processImmediate (internal/timers.js:456:21)

I assume request went to another state because it's cancelled but the timer still fired in 5 sec.

So, I am wondering what could be the issue here and under which circumstances this happens? And should increasing timeout is the only solution?

I am using mssql module based on tedious 6.7.0. Please let me know if anything pops up. Thanks.

[IanChokS]

@gsamal Can you show the log output for the first error you've received?

[gsamal]

@IanChokS The following is the first error I got with simple execute query.

RequestError: Failed to cancel request in 5000ms
    at Request.userCallback (/node_modules/mssql/lib/tedious/request.js:429:19)
    at Request.callback (/node_modules/tedious/lib/request.js:56:14)
    at Connection.socketError (/node_modules/tedious/lib/connection.js:2421:20)
    at Connection.dispatchEvent (/node_modules/tedious/lib/connection.js:1279:15)
    at Connection.cancelTimeout (/node_modules/tedious/lib/connection.js:1203:10)
    at Timeout._onTimeout (/node_modules/tedious/lib/connection.js:1167:14)
    at listOnTimeout (internal/timers.js:549:17)
    at processTimers (internal/timers.js:492:7)

[IanChokS]

@gsamal Yeah it looks like something triggered the cancel for the request while it was processing, but the log outputs don't show what started the cancel event in the first place. Try to see if you can find some type of timer that allots a certain total amount of time for a query process that cancels a request once that timer limit is hit.

[arthurschreiber]

There is a default request timeout of 15000ms for every connection. That means if it takes longer than 15000ms from the time the request was started till the time last response chunk was processed by tedious, a request will automatically be canceled.

Once the cancellation was sent to the server, there is a timeout of 5000ms for the server to respond. If the server does not respond in that timeframe, the connection will be in an undefined state and can't be reused. There's nothing we can really do about that itself, but we should be able to better convey this in the error messages and documentation.

Note that in this case you don't need to rollback the transaction - as the connection becomes unusable that means it will never commit and the transaction will be rolled back by the server automatically once the TCP connection to the server is closed.

[gautamsamal]

@arthurschreiber thanks for explaining the control flow. I kind of figured that out. Although I consider it to be a nice point, not to rollback the transaction since the request in already invalid and the connection is probably disconnected from server.

However I can't do that gracefully since the error code is similar as the request timeout. So, this is what I could do.

    try {
      // Handles internally via requestId.
      await this.connection.rollbackTransaction(requestId);
    } catch (err) {
      if (err.code === 'EINVALIDSTATE') {
        this.log.warn('The request is already in disconnected state. No actions needed.');
      } else {
        this.log.error('Cannot rollback transaction. Exception :', err);
        throw err;
      }
    }

Does this make sense?

[ekelvin]

we find the exact same issue in a transaction with not explanation why is happening

[MichaelSun90]

Hi, @gautamsamal and @ekelvin , in terms of the comment regarding the error code:

However I can't do that gracefully since the error code is similar to the request timeout. So, this is what I could do.

This may not be ideal, but the error name for these two errors can be used to distinguish whether it is a request or a connection time-out error. If you catch an error code "ETIMEOUT" for a ConnectionError, and do an error.name, this should return term "connect" for a connectTimeout or term"socketError" for cancelTimeout. If the error is for requestTimeout, then the error will be thrown as a RequestError with the error code "ETIMEOUT".

Also, like @arthurschreiber mention in his comment, we will also add some explanation to the document page for this time-out behavior, so it will be easier to understand. We could also refactor the error handling process in the future to add a more organized error code and message structure, so the errors will be more clear to users.